1. recv 1529 bytes from udp/[139.59.19.72]:5060 at 19:48:44.618377:
2.    ------------------------------------------------------------------------
3.    INVITE sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test SIP/2.0
4.    Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKS3Q3S5merHy4p
5.    Max-Forwards: 69
6.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
7.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>
8.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
9.    CSeq: 123518797 INVITE
10.    Contact: <sip:mod_sofia@139.59.19.72:5060>
11.    User-Agent: Shashi-switch-sip
12.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
13.    Supported: timer, path, replaces
14.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
15.    Session-Expires: 120;refresher=uac
16.    Min-SE: 120
17.    Content-Type: application/sdp
18.    Content-Disposition: session
19.    Content-Length: 491
20.    X-FS-Support: update_display,send_info
21.    Remote-Party-ID: "Extension 1000" <sip:1000@139.59.19.72>;party=calling;screen=yes;privacy=off
22.  
23.    v=0
24.    o=Shashi-switch-sdp 1527689106 1527689107 IN IP4 139.59.19.72
25.    s=Shashi-switch-sdp
26.    c=IN IP4 139.59.19.72
27.    t=0 0
28.    m=audio 20616 RTP/AVP 102 9 0 8 103 101
29.    a=rtpmap:102 opus/48000/2
30.    a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
31.    a=rtpmap:9 G722/8000
32.    a=rtpmap:0 PCMU/8000
33.    a=rtpmap:8 PCMA/8000
34.    a=rtpmap:103 telephone-event/48000
35.    a=fmtp:103 0-16
36.    a=rtpmap:101 telephone-event/8000
37.    a=fmtp:101 0-16
38.    a=ptime:20
39.    ------------------------------------------------------------------------
40. 2018-05-30 19:48:44.613113 [NOTICE] switch_channel.c:1104 New Channel sofia/external/1000@139.59.19.72 [7908aba4-48e6-40ac-832f-f7ca7ce7be11]
41. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_NEW (Cur 1 Tot 12)
42. 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:10078 sofia/external/1000@139.59.19.72 receiving invite from 139.59.19.72:5060 version: 1.9.0 git ed4920e 2018-05-04 14:37:06Z 64bit
43. 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [received][100]
44. 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:7301 Remote SDP:
45. v=0
46. o=Shashi-switch-sdp 1527689106 1527689107 IN IP4 139.59.19.72
47. s=Shashi-switch-sdp
48. c=IN IP4 139.59.19.72
49. t=0 0
50. m=audio 20616 RTP/AVP 102 9 0 8 103 101
51. a=rtpmap:102 opus/48000/2
52. a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
53. a=rtpmap:9 G722/8000
54. a=rtpmap:0 PCMU/8000
55. a=rtpmap:8 PCMA/8000
56. a=rtpmap:103 telephone-event/48000
57. a=fmtp:103 0-16
58. a=rtpmap:101 telephone-event/8000
59. a=fmtp:101 0-16
60. a=ptime:20
61.  
62. 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:7693 (sofia/external/1000@139.59.19.72) State Change CS_NEW -> CS_INIT
63. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:603 (sofia/external/1000@139.59.19.72) State NEW
64. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_INIT (Cur 1 Tot 12)
65. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1000@139.59.19.72) State INIT
66. 2018-05-30 19:48:44.613113 [DEBUG] mod_sofia.c:93 sofia/external/1000@139.59.19.72 SOFIA INIT
67. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:40 sofia/external/1000@139.59.19.72 Standard INIT
68. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:48 (sofia/external/1000@139.59.19.72) State Change CS_INIT -> CS_ROUTING
69. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1000@139.59.19.72) State INIT going to sleep
70. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_ROUTING (Cur 1 Tot 12)
71. 2018-05-30 19:48:44.613113 [DEBUG] switch_channel.c:2249 (sofia/external/1000@139.59.19.72) Callstate Change DOWN -> RINGING
72. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1000@139.59.19.72) State ROUTING
73. send 401 bytes to udp/[139.59.19.72]:5060 at 19:48:44.619491:
74.    ------------------------------------------------------------------------
75.    SIP/2.0 100 Trying
76.    Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKS3Q3S5merHy4p
77.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
78.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>
79.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
80.    CSeq: 123518797 INVITE
81.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
82.    Content-Length: 0
83.  
84.    ------------------------------------------------------------------------
85. 2018-05-30 19:48:44.613113 [DEBUG] mod_sofia.c:154 sofia/external/1000@139.59.19.72 SOFIA ROUTING
86. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:236 sofia/external/1000@139.59.19.72 Standard ROUTING
87. 2018-05-30 19:48:44.613113 [INFO] mod_dialplan_xml.c:637 Processing Extension 1000 <1000>->1001 in context public
88. Dialplan: sofia/external/1000@139.59.19.72 parsing [public->record_rest] continue=false
89. Dialplan: sofia/external/1000@139.59.19.72 Regex (PASS) [record_rest] ${destination_number}(1001) =~ /1001/ break=on-false
90. Dialplan: sofia/external/1000@139.59.19.72 Action answer()
91. Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_TITLE=Recording ${destination_number} ${caller_id_number} ${strftime(%Y-%m-%d %H:%M)})
92. Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_COPYRIGHT=(c) 1980 Factory Records, Inc.)
93. Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_SOFTWARE=FreeSWITCH)
94. Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_ARTIST=Ian Curtis)
95. Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_COMMENT=Love will tear us apart)
96. Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_DATE=${strftime(%Y-%m-%d %H:%M)})
97. Dialplan: sofia/external/1000@139.59.19.72 Action set(RECORD_STEREO=true)
98. Dialplan: sofia/external/1000@139.59.19.72 Action record_session(/usr/local/freeswitch/recordings/${strftime(%Y-%m-%d-%H-%M-%S)}_${destination_number}_${caller_id_number}.wav)
99.  
100. Dialplan: sofia/external/1000@139.59.19.72 Action set(ringback=${us-ring})
101. Dialplan: sofia/external/1000@139.59.19.72 Action bridge(user/1003)
102. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:286 (sofia/external/1000@139.59.19.72) State Change CS_ROUTING -> CS_EXECUTE
103. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1000@139.59.19.72) State ROUTING going to sleep
104. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_EXECUTE (Cur 1 Tot 12)
105. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1000@139.59.19.72) State EXECUTE
106. 2018-05-30 19:48:44.613113 [DEBUG] mod_sofia.c:209 sofia/external/1000@139.59.19.72 SOFIA EXECUTE
107. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_state_machine.c:328 sofia/external/1000@139.59.19.72 Standard EXECUTE
108. EXECUTE sofia/external/1000@139.59.19.72 answer()
109. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[opus:116:48000:20:0:1]
110. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
111. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[G722:9:8000:20:64000:1]
112. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
113. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
114. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
115. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
116. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
117. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
118. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
119. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
120. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
121. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
122. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
123. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
124. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
125. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
126. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
127. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
128. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
129. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5047 Set telephone-event payload to 103@48000
130. 2018-05-30 19:48:44.613113 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
131. 2018-05-30 19:48:44.613113 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
132. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:3446 Set Codec sofia/external/1000@139.59.19.72 opus/48000 20 ms 960 samples 0 bits 2 channels
133. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_codec.c:111 sofia/external/1000@139.59.19.72 Original read codec set to opus:116
134. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5390 Set telephone-event payload to 103@48000
135. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:5448 sofia/external/1000@139.59.19.72 Set 2833 dtmf send payload to 103 recv payload to 103
136. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8164 AUDIO RTP [sofia/external/1000@139.59.19.72] 159.89.163.195 port 28298 -> 139.59.19.72 port 20616 codec: 102 ms: 20
137. 2018-05-30 19:48:44.613113 [DEBUG] switch_rtp.c:4189 Starting timer [soft] 960 bytes per 20ms
138. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8468 sofia/external/1000@139.59.19.72 Set 2833 dtmf send payload to 103
139. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8475 sofia/external/1000@139.59.19.72 Set 2833 dtmf receive payload to 103
140. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8498 sofia/external/1000@139.59.19.72 Set rtp dtmf delay to 40
141. 2018-05-30 19:48:44.613113 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/1000@139.59.19.72!
142. 2018-05-30 19:48:44.613113 [DEBUG] switch_channel.c:3482 (sofia/external/1000@139.59.19.72) Callstate Change RINGING -> EARLY
143. 2018-05-30 19:48:44.613113 [DEBUG] switch_core_media.c:8147 Audio params are unchanged for sofia/external/1000@139.59.19.72.
144. 2018-05-30 19:48:44.613113 [DEBUG] mod_sofia.c:881 Local SDP sofia/external/1000@139.59.19.72:
145. v=0
146. o=FreeSWITCH 1527681426 1527681427 IN IP4 159.89.163.195
147. s=FreeSWITCH
148. c=IN IP4 159.89.163.195
149. t=0 0
150. m=audio 28298 RTP/AVP 102 103
151. a=rtpmap:102 opus/48000/2
152. a=fmtp:102 useinbandfec=1; ptime=20; minptime=10; maxptime=40; stereo=1
153. a=rtpmap:103 telephone-event/48000
154. a=fmtp:103 0-16
155. a=ptime:20
156. a=sendrecv
157.  
158. send 1292 bytes to udp/[139.59.19.72]:5060 at 19:48:44.622729:
159.    ------------------------------------------------------------------------
160.    SIP/2.0 200 OK
161.    Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKS3Q3S5merHy4p
162.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
163.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
164.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
165.    CSeq: 123518797 INVITE
166.    Contact: <sip:gw+record_test@159.89.163.195:5040;transport=udp>
167.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
168.    Accept: application/sdp
169.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
170.    Require: timer
171.    Supported: timer, path, replaces
172.    Allow-Events: talk, hold, conference, refer
173.    Session-Expires: 120;refresher=uac
174.    Content-Type: application/sdp
175.    Content-Disposition: session
176.    Content-Length: 305
177.    X-FS-Display-Name: 1001
178.    X-FS-Display-Number: sip:1001@159.89.163.195
179.    X-FS-Support: update_display,send_info
180.    Remote-Party-ID: "1001" <sip:1001@159.89.163.195>;party=calling;privacy=off;screen=no
181.  
182.    v=0
183.    o=FreeSWITCH 1527681426 1527681427 IN IP4 159.89.163.195
184.    s=FreeSWITCH
185.    c=IN IP4 159.89.163.195
186.    t=0 0
187.    m=audio 28298 RTP/AVP 102 103
188.    a=rtpmap:102 opus/48000/2
189.    a=fmtp:102 useinbandfec=1; ptime=20; minptime=10; maxptime=40; stereo=1
190.    a=rtpmap:103 telephone-event/48000
191.    a=fmtp:103 0-16
192.    a=ptime:20
193.    ------------------------------------------------------------------------
194. 2018-05-30 19:48:44.613113 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [completed][200]
195. 2018-05-30 19:48:44.613113 [NOTICE] mod_dptools.c:1357 Channel [sofia/external/1000@139.59.19.72] has been answered
196. 2018-05-30 19:48:44.623061 [DEBUG] switch_channel.c:3781 (sofia/external/1000@139.59.19.72) Callstate Change EARLY -> ACTIVE
197. EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_TITLE=Recording 1001 1000 2018-05-30 19:48)
198. 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_TITLE]=[Recording 1001 1000 2018-05-30 19:48]
199. EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_COPYRIGHT=(c) 1980 Factory Records, Inc.)
200. 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_COPYRIGHT]=[(c) 1980 Factory Records, Inc.]
201. EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_SOFTWARE=FreeSWITCH)
202. 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_SOFTWARE]=[FreeSWITCH]
203. EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_ARTIST=Ian Curtis)
204. 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_ARTIST]=[Ian Curtis]
205. EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_COMMENT=Love will tear us apart)
206. 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_COMMENT]=[Love will tear us apart]
207. EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_DATE=2018-05-30 19:48)
208. 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_DATE]=[2018-05-30 19:48]
209. EXECUTE sofia/external/1000@139.59.19.72 set(RECORD_STEREO=true)
210. 2018-05-30 19:48:44.623061 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [RECORD_STEREO]=[true]
211. EXECUTE sofia/external/1000@139.59.19.72 record_session(/usr/local/freeswitch/recordings/2018-05-30-19-48-44_1001_1000.wav)
212. recv 441 bytes from udp/[139.59.19.72]:5060 at 19:48:44.625458:
213.    ------------------------------------------------------------------------
214.    ACK sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0
215.    Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKtcHvU05HNtmQj
216.    Max-Forwards: 70
217.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
218.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
219.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
220.    CSeq: 123518797 ACK
221.    Contact: <sip:mod_sofia@139.59.19.72:5060>
222.    Content-Length: 0
223.  
224.    ------------------------------------------------------------------------
225. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/external/1000@139.59.19.72
226. 2018-05-30 19:48:44.633064 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [ready][200]
227. EXECUTE sofia/external/1000@139.59.19.72 set(ringback=%(2000,4000,440,480))
228. 2018-05-30 19:48:44.633064 [DEBUG] mod_dptools.c:1593 SET sofia/external/1000@139.59.19.72 [ringback]=[%(2000,4000,440,480)]
229. EXECUTE sofia/external/1000@139.59.19.72 bridge(user/1003)
230. 2018-05-30 19:48:44.633064 [DEBUG] switch_channel.c:1823 (sofia/external/1000@139.59.19.72) Callstate Change ACTIVE -> RING_WAIT
231. 2018-05-30 19:48:44.633064 [DEBUG] switch_ivr_originate.c:2159 Parsing global variables
232. 2018-05-30 19:48:44.633064 [DEBUG] switch_ivr_originate.c:2159 Parsing global variables
233. 2018-05-30 19:48:44.633064 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1003@124.123.68.233:10222 [e66214b9-c6df-4e56-a9d9-15aa00d65775]
234. 2018-05-30 19:48:44.633064 [DEBUG] mod_sofia.c:5026 (sofia/internal/1003@124.123.68.233:10222) State Change CS_NEW -> CS_INIT
235. 2018-05-30 19:48:44.633064 [NOTICE] switch_ivr_originate.c:2868 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
236. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_INIT (Cur 2 Tot 13)
237. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1003@124.123.68.233:10222) State INIT
238. 2018-05-30 19:48:44.633064 [DEBUG] mod_sofia.c:93 sofia/internal/1003@124.123.68.233:10222 SOFIA INIT
239. 2018-05-30 19:48:44.633064 [DEBUG] sofia_glue.c:1299 sofia/internal/1003@124.123.68.233:10222 sending invite version: 1.9.0 git ed4920e 2018-05-04 14:37:06Z 64bit
240. Local SDP:
241. v=0
242. o=FreeSWITCH 1527688610 1527688611 IN IP4 159.89.163.195
243. s=FreeSWITCH
244. c=IN IP4 159.89.163.195
245. t=0 0
246. m=audio 21114 RTP/AVP 102 101
247. a=rtpmap:102 opus/48000/2
248. a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
249. a=rtpmap:101 telephone-event/48000
250. a=fmtp:101 0-16
251. a=ptime:20
252. a=sendrecv
253.  
254. send 1406 bytes to tcp/[124.123.68.233]:10222 at 19:48:44.641242:
255.    ------------------------------------------------------------------------
256.    INVITE sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92 SIP/2.0
257.    Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKr6g3ZcgBeFr8Q
258.    Max-Forwards: 68
259.    From: "Extension 1000" <sip:1000@159.89.163.195>;tag=03e14v3jr65Ua
260.    To: <sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92>
261.    Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88
262.    CSeq: 123518798 INVITE
263.    Contact: <sip:mod_sofia@159.89.163.195:5020;transport=tcp>
264.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
265.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
266.    Supported: timer, path, replaces
267.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
268.    Content-Type: application/sdp
269.    Content-Disposition: session
270.    Content-Length: 343
271.    X-FS-Support: update_display,send_info
272.    Remote-Party-ID: "Extension 1000" <sip:1000@159.89.163.195>;party=calling;screen=yes;privacy=off
273.  
274.    v=0
275.    o=FreeSWITCH 1527688610 1527688611 IN IP4 159.89.163.195
276.    s=FreeSWITCH
277.    c=IN IP4 159.89.163.195
278.    t=0 0
279.    m=audio 21114 RTP/AVP 102 101
280.    a=rtpmap:102 opus/48000/2
281.    a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
282.    a=rtpmap:101 telephone-event/48000
283.    a=fmtp:101 0-16
284.    a=ptime:20
285.    ------------------------------------------------------------------------
286. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003@124.123.68.233:10222 Standard INIT
287. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003@124.123.68.233:10222) State Change CS_INIT -> CS_ROUTING
288. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1003@124.123.68.233:10222) State INIT going to sleep
289. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_ROUTING (Cur 2 Tot 13)
290. 2018-05-30 19:48:44.633064 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@124.123.68.233:10222 entering state [calling][0]
291. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1003@124.123.68.233:10222) State ROUTING
292. 2018-05-30 19:48:44.633064 [DEBUG] mod_sofia.c:154 sofia/internal/1003@124.123.68.233:10222 SOFIA ROUTING
293. 2018-05-30 19:48:44.633064 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1003@124.123.68.233:10222) State Change CS_ROUTING -> CS_CONSUME_MEDIA
294. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1003@124.123.68.233:10222) State ROUTING going to sleep
295. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 13)
296. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1003@124.123.68.233:10222) State CONSUME_MEDIA
297. 2018-05-30 19:48:44.633064 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1003@124.123.68.233:10222) State CONSUME_MEDIA going to sleep
298. 2018-05-30 19:48:44.633064 [DEBUG] switch_ivr_async.c:1508 No silence detection configured; assuming start of speech
299. freeswitch@debian-s-1vcpu-1gb-blr1-01>
300. freeswitch@debian-s-1vcpu-1gb-blr1-01>
301. recv 324 bytes from tcp/[124.123.68.233]:10222 at 19:48:44.742629:
302.    ------------------------------------------------------------------------
303.    SIP/2.0 100 Trying
304.    Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKr6g3ZcgBeFr8Q
305.    To: <sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92>
306.    From: "Extension 1000" <sip:1000@159.89.163.195>;tag=03e14v3jr65Ua
307.    Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88
308.    CSeq: 123518798 INVITE
309.    Content-Length: 0
310.  
311.    ------------------------------------------------------------------------
312. freeswitch@debian-s-1vcpu-1gb-blr1-01>
313. freeswitch@debian-s-1vcpu-1gb-blr1-01>
314. freeswitch@debian-s-1vcpu-1gb-blr1-01>
315. freeswitch@debian-s-1vcpu-1gb-blr1-01>
316. freeswitch@debian-s-1vcpu-1gb-blr1-01>
317. recv 718 bytes from udp/[139.59.19.72]:5060 at 19:48:44.946359:
318.    ------------------------------------------------------------------------
319.   INFO sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0
320.    Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKUNaNXUpNj3aae
321.    Max-Forwards: 70
322.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
323.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
324.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
325.   CSeq: 123518798 INFO
326.    Contact: <sip:mod_sofia@139.59.19.72:5060>
327.    User-Agent: Shashi-switch-sip
328.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
329.    Supported: timer, path, replaces
330.    Content-Type: message/update_display
331.    Content-Length: 0
332.    X-FS-Display-Name: Extension 1000
333.    X-FS-Display-Number: 1000
334.  
335.    ------------------------------------------------------------------------
336. send 537 bytes to udp/[139.59.19.72]:5060 at 19:48:44.961574:
337.    ------------------------------------------------------------------------
338.    SIP/2.0 200 OK
339.    Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKUNaNXUpNj3aae
340.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
341.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
342.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
343.   CSeq: 123518798 INFO
344.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
345.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
346.    Supported: timer, path, replaces
347.    Content-Length: 0
348.  
349.    ------------------------------------------------------------------------
350. 2018-05-30 19:48:45.113092 [DEBUG] switch_rtp.c:7373 Correct audio ip/port confirmed.
351. 2018-05-30 19:48:45.113092 [DEBUG] switch_core_io.c:448 Setting BUG Codec opus:116
352. 2018-05-30 19:48:45.113092 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
353. recv 544 bytes from tcp/[124.123.68.233]:10222 at 19:48:45.747861:
354.    ------------------------------------------------------------------------
355.    SIP/2.0 180 Ringing
356.    Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKr6g3ZcgBeFr8Q
357.    Contact: <sip:1003@124.123.68.233:10222;transport=TCP>
358.    To: <sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92>;tag=b0260860
359.    From: "Extension 1000" <sip:1000@159.89.163.195>;tag=03e14v3jr65Ua
360.    Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88
361.    CSeq: 123518798 INVITE
362.   Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
363.    User-Agent: Z 5.2.14 rv2.8.88
364.    Allow-Events: presence, kpml, talk
365.    Content-Length: 0
366.  
367.    ------------------------------------------------------------------------
368. 2018-05-30 19:48:45.743076 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@124.123.68.233:10222 entering state [proceeding][180]
369. 2018-05-30 19:48:45.743076 [NOTICE] sofia.c:7399 Ring-Ready sofia/internal/1003@124.123.68.233:10222!
370. 2018-05-30 19:48:45.743076 [DEBUG] switch_channel.c:3354 (sofia/internal/1003@124.123.68.233:10222) Callstate Change DOWN -> RINGING
371. 2018-05-30 19:48:45.773076 [DEBUG] switch_ivr_originate.c:1278 Raw Codec Activation Success L16@48000hz 2 channel 20ms
372. 2018-05-30 19:48:45.773076 [DEBUG] switch_core_codec.c:223 sofia/external/1000@139.59.19.72 Push codec L16:100
373. 2018-05-30 19:48:45.773076 [DEBUG] switch_ivr_originate.c:1347 Play Ringback Tone [%(2000,4000,440,480)]
374. recv 1159 bytes from tcp/[124.123.68.233]:10222 at 19:48:49.854699:
375.    ------------------------------------------------------------------------
376.    SIP/2.0 200 OK
377.    Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKr6g3ZcgBeFr8Q
378.    Contact: <sip:1003@124.123.68.233:10222;transport=TCP>
379.    To: <sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92>;tag=b0260860
380.    From: "Extension 1000" <sip:1000@159.89.163.195>;tag=03e14v3jr65Ua
381.    Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88
382.    CSeq: 123518798 INVITE
383.   Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
384.    Content-Type: application/sdp
385.    User-Agent: Z 5.2.14 rv2.8.88
386.    Allow-Events: presence, kpml, talk
387.    Content-Length: 587
388.  
389.    v=0
390.    o=Z 0 1 IN IP4 10.144.160.39
391.    s=Z
392.    c=IN IP4 10.144.160.39
393.    t=0 0
394.    m=audio 8000 RTP/AVP 102 9 3 111 0 8 97 110 112 96 98 101 100 99
395.    a=rtpmap:102 opus/48000/2
396.    a=fmtp:102 cbr=1; maxaveragebitrate=30000; useinbandfec=1
397.    a=rtpmap:111 speex/16000
398.    a=rtpmap:97 iLBC/8000
399.    a=fmtp:97 mode=20
400.    a=rtpmap:110 speex/8000
401.    a=rtpmap:112 speex/32000
402.    a=rtpmap:96 G726-32/8000
403.    a=rtpmap:98 telephone-event/48000
404.    a=fmtp:98 0-16
405.    a=rtpmap:101 telephone-event/8000
406.    a=fmtp:101 0-16
407.    a=rtpmap:100 telephone-event/16000
408.    a=fmtp:100 0-16
409.    a=rtpmap:99 telephone-event/32000
410.    a=fmtp:99 0-16
411.    a=sendrecv
412.    ------------------------------------------------------------------------
413. 2018-05-30 19:48:49.853075 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@124.123.68.233:10222 entering state [completing][200]
414. 2018-05-30 19:48:49.853075 [DEBUG] sofia.c:7301 Remote SDP:
415. v=0
416. o=Z 0 1 IN IP4 10.144.160.39
417. s=Z
418. c=IN IP4 10.144.160.39
419. t=0 0
420. m=audio 8000 RTP/AVP 102 9 3 111 0 8 97 110 112 96 98 101 100 99
421. a=rtpmap:102 opus/48000/2
422. a=fmtp:102 cbr=1; maxaveragebitrate=30000; useinbandfec=1
423. a=rtpmap:111 speex/16000
424. a=rtpmap:97 iLBC/8000
425. a=fmtp:97 mode=20
426. a=rtpmap:110 speex/8000
427. a=rtpmap:112 speex/32000
428. a=rtpmap:96 G726-32/8000
429. a=rtpmap:98 telephone-event/48000
430. a=fmtp:98 0-16
431. a=rtpmap:101 telephone-event/8000
432. a=fmtp:101 0-16
433. a=rtpmap:100 telephone-event/16000
434. a=fmtp:100 0-16
435. a=rtpmap:99 telephone-event/32000
436. a=fmtp:99 0-16
437.  
438. send 449 bytes to tcp/[124.123.68.233]:10222 at 19:48:49.856059:
439.    ------------------------------------------------------------------------
440.    ACK sip:1003@124.123.68.233:10222;transport=TCP SIP/2.0
441.    Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKSFav170eBreUK
442.    Max-Forwards: 70
443.    From: "Extension 1000" <sip:1000@159.89.163.195>;tag=03e14v3jr65Ua
444.    To: <sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92>;tag=b0260860
445.    Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88
446.    CSeq: 123518798 ACK
447.    Contact: <sip:mod_sofia@159.89.163.195:5020;transport=tcp>
448.    Content-Length: 0
449.  
450.    ------------------------------------------------------------------------
451. 2018-05-30 19:48:49.853075 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@124.123.68.233:10222 entering state [ready][200]
452. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
453. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
454. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
455. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
456. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [speex:111:16000:20:0:1]/[opus:116:48000:20:0:1]
457. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
458. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
459. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [iLBC:97:8000:30:0:1]/[opus:116:48000:20:0:1]
460. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [speex:110:8000:20:0:1]/[opus:116:48000:20:0:1]
461. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [speex:112:32000:20:0:1]/[opus:116:48000:20:0:1]
462. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G726-32:96:8000:20:0:1]/[opus:116:48000:20:0:1]
463. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5047 Set telephone-event payload to 98@48000
464. 2018-05-30 19:48:49.853075 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps]
465. 2018-05-30 19:48:49.853075 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps]
466. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:3446 Set Codec sofia/internal/1003@124.123.68.233:10222 opus/48000 20 ms 960 samples 0 bits 1 channels
467. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_codec.c:111 sofia/internal/1003@124.123.68.233:10222 Original read codec set to opus:116
468. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5390 Set telephone-event payload to 98@48000
469. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:5448 sofia/internal/1003@124.123.68.233:10222 Set 2833 dtmf send payload to 98 recv payload to 101
470. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:8164 AUDIO RTP [sofia/internal/1003@124.123.68.233:10222] 159.89.163.195 port 21114 -> 10.144.160.39 port 8000 codec: 102 ms: 20
471. 2018-05-30 19:48:49.853075 [DEBUG] switch_rtp.c:4189 Starting timer [soft] 960 bytes per 20ms
472. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:8468 sofia/internal/1003@124.123.68.233:10222 Set 2833 dtmf send payload to 98
473. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:8475 sofia/internal/1003@124.123.68.233:10222 Set 2833 dtmf receive payload to 101
474. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_media.c:8498 sofia/internal/1003@124.123.68.233:10222 Set rtp dtmf delay to 40
475. 2018-05-30 19:48:49.853075 [NOTICE] sofia.c:8427 Channel [sofia/internal/1003@124.123.68.233:10222] has been answered
476. 2018-05-30 19:48:49.853075 [DEBUG] switch_channel.c:3781 (sofia/internal/1003@124.123.68.233:10222) Callstate Change RINGING -> ACTIVE
477. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_codec.c:248 sofia/external/1000@139.59.19.72 Restore previous codec opus:116.
478. 2018-05-30 19:48:49.853075 [DEBUG] switch_ivr_originate.c:3722 Originate Resulted in Success: [sofia/internal/1003@124.123.68.233:10222]
479. 2018-05-30 19:48:49.853075 [DEBUG] switch_channel.c:2047 (sofia/external/1000@139.59.19.72) Callstate Change RING_WAIT -> ACTIVE
480. 2018-05-30 19:48:49.853075 [DEBUG] switch_ivr_originate.c:3722 Originate Resulted in Success: [sofia/internal/1003@124.123.68.233:10222]
481. 2018-05-30 19:48:49.853075 [DEBUG] switch_ivr_bridge.c:1744 (sofia/internal/1003@124.123.68.233:10222) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
482. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 13)
483. 2018-05-30 19:48:49.853075 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1003@124.123.68.233:10222) State EXCHANGE_MEDIA
484. 2018-05-30 19:48:49.853075 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA
485. 2018-05-30 19:48:49.873061 [DEBUG] switch_core_media.c:15475 Engaging Write Buffer at 3840 bytes to accommodate 3840->3840
486. send 751 bytes to udp/[139.59.19.72]:5060 at 19:48:49.881736:
487.    ------------------------------------------------------------------------
488.   INFO sip:mod_sofia@139.59.19.72:5060 SIP/2.0
489.    Via: SIP/2.0/UDP 159.89.163.195:5040;rport;branch=z9hG4bK77av27XeceyKN
490.    Max-Forwards: 70
491.    From: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
492.    To: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
493.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
494.   CSeq: 123518800 INFO
495.    Contact: <sip:gw+record_test@159.89.163.195:5040;transport=udp>
496.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
497.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
498.    Supported: timer, path, replaces
499.    Content-Type: message/update_display
500.    Content-Length: 0
501.    X-FS-Display-Name: Outbound Call
502.    X-FS-Display-Number: 1003
503.  
504.    ------------------------------------------------------------------------
505. recv 517 bytes from udp/[139.59.19.72]:5060 at 19:48:49.888236:
506.    ------------------------------------------------------------------------
507.    SIP/2.0 200 OK
508.    Via: SIP/2.0/UDP 159.89.163.195:5040;rport=5040;branch=z9hG4bK77av27XeceyKN
509.    From: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
510.    To: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
511.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
512.   CSeq: 123518800 INFO
513.    User-Agent: Shashi-switch-sip
514.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
515.    Supported: timer, path, replaces
516.    Content-Length: 0
517.  
518.    ------------------------------------------------------------------------
519. 2018-05-30 19:48:49.913076 [DEBUG] switch_core_media.c:15475 Engaging Write Buffer at 1920 bytes to accommodate 1920->1920
520. 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
521. 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[239] Bytes encoded[36357] Encoded length ms[4780] Average encoded bitrate bps[72714]
522. 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
523. 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[237] PLC[0] FEC[0]
524. 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
525. 2018-05-30 19:48:50.573079 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
526. 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
527. 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[8] Bytes encoded[1408] Encoded length ms[160] Average encoded bitrate bps[0]
528. 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
529. 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[8] PLC[0] FEC[0]
530. 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
531. 2018-05-30 19:48:50.733065 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
532. 2018-05-30 19:48:50.793082 [INFO] switch_rtp.c:7333 Auto Changing audio port from 10.144.160.39:8000 to 124.123.68.233:10231
533. 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
534. 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[9] Bytes encoded[1243] Encoded length ms[180] Average encoded bitrate bps[0]
535. 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
536. 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[9] PLC[0] FEC[0]
537. 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
538. 2018-05-30 19:48:50.913094 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
539. 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
540. 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[19] Bytes encoded[2245] Encoded length ms[380] Average encoded bitrate bps[0]
541. 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
542. 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[19] PLC[0] FEC[0]
543. 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
544. 2018-05-30 19:48:51.293088 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
545. 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
546. 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[53] Bytes encoded[10088] Encoded length ms[1060] Average encoded bitrate bps[80704]
547. 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
548. 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[53] PLC[0] FEC[0]
549. 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
550. 2018-05-30 19:48:52.353090 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
551. 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
552. 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[261] Bytes encoded[58017] Encoded length ms[5220] Average encoded bitrate bps[92827]
553. 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
554. 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[259] PLC[0] FEC[0]
555. 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
556. 2018-05-30 19:48:57.533080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
557. 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
558. 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[23] Bytes encoded[3966] Encoded length ms[460] Average encoded bitrate bps[0]
559. 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
560. 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[23] PLC[0] FEC[0]
561. 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
562. 2018-05-30 19:48:57.993098 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
563. 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
564. 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[195] Bytes encoded[42168] Encoded length ms[3900] Average encoded bitrate bps[112448]
565. 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
566. 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[195] PLC[0] FEC[0]
567. 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
568. 2018-05-30 19:49:01.893084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
569. 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
570. 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[137] Bytes encoded[26772] Encoded length ms[2740] Average encoded bitrate bps[107088]
571. 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
572. 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[137] PLC[0] FEC[0]
573. 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
574. 2018-05-30 19:49:04.633083 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
575. 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
576. 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[56] Bytes encoded[10841] Encoded length ms[1120] Average encoded bitrate bps[86728]
577. 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
578. 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[56] PLC[0] FEC[0]
579. 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
580. 2018-05-30 19:49:05.753076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
581. 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
582. 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[17] Bytes encoded[3572] Encoded length ms[340] Average encoded bitrate bps[0]
583. 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
584. 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[17] PLC[0] FEC[0]
585. 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
586. 2018-05-30 19:49:06.093084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
587. 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
588. 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[81] Bytes encoded[13269] Encoded length ms[1620] Average encoded bitrate bps[106152]
589. 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
590. 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[81] PLC[0] FEC[0]
591. 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
592. 2018-05-30 19:49:07.713080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
593. 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
594. 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[41] Bytes encoded[6703] Encoded length ms[820] Average encoded bitrate bps[0]
595. 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
596. 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[41] PLC[0] FEC[0]
597. 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
598. 2018-05-30 19:49:08.533104 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
599. 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
600. 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[304] Bytes encoded[57137] Encoded length ms[6080] Average encoded bitrate bps[76182]
601. 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
602. 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[304] PLC[0] FEC[0]
603. 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
604. 2018-05-30 19:49:14.613116 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
605. 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
606. 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[345] Bytes encoded[72122] Encoded length ms[6900] Average encoded bitrate bps[96162]
607. 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
608. 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[341] PLC[0] FEC[0]
609. 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
610. 2018-05-30 19:49:21.513085 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
611. 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
612. 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[64] Bytes encoded[9565] Encoded length ms[1280] Average encoded bitrate bps[76520]
613. 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
614. 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[64] PLC[0] FEC[0]
615. 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
616. 2018-05-30 19:49:22.793080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
617. 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
618. 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[299] Bytes encoded[58216] Encoded length ms[5980] Average encoded bitrate bps[93145]
619. 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
620. 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[295] PLC[0] FEC[0]
621. 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
622. 2018-05-30 19:49:28.773076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
623. 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
624. 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[94] Bytes encoded[17986] Encoded length ms[1880] Average encoded bitrate bps[143888]
625. 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
626. 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[94] PLC[0] FEC[0]
627. 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
628. 2018-05-30 19:49:30.653086 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
629. 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
630. 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[34] Bytes encoded[5569] Encoded length ms[680] Average encoded bitrate bps[0]
631. 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
632. 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[34] PLC[0] FEC[0]
633. 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
634. 2018-05-30 19:49:31.333076 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
635. 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
636. 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[25] Bytes encoded[3857] Encoded length ms[500] Average encoded bitrate bps[0]
637. 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
638. 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[25] PLC[0] FEC[0]
639. 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
640. 2018-05-30 19:49:31.833084 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
641. 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
642. 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[73] Bytes encoded[13469] Encoded length ms[1460] Average encoded bitrate bps[107752]
643. 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
644. 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[73] PLC[0] FEC[0]
645. 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
646. 2018-05-30 19:49:33.293080 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
647. 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
648. 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[165] Bytes encoded[26370] Encoded length ms[3300] Average encoded bitrate bps[70320]
649. 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
650. 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[165] PLC[0] FEC[0]
651. 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
652. 2018-05-30 19:49:36.593085 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
653. 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
654. 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[79] Bytes encoded[13171] Encoded length ms[1580] Average encoded bitrate bps[105368]
655. 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
656. 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[79] PLC[0] FEC[0]
657. 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
658. 2018-05-30 19:49:38.173083 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
659. recv 1361 bytes from udp/[139.59.19.72]:5060 at 19:49:40.276099:
660.    ------------------------------------------------------------------------
661.    INVITE sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0
662.    Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKvy3DZp7rFc1vS
663.    Max-Forwards: 69
664.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
665.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
666.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
667.    CSeq: 123518799 INVITE
668.    Contact: <sip:mod_sofia@139.59.19.72:5060>
669.    User-Agent: Shashi-switch-sip
670.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
671.    Supported: timer, path, replaces
672.    Session-Expires: 120;refresher=uac
673.    Min-SE: 120
674.    Content-Type: application/sdp
675.    Content-Disposition: session
676.    Content-Length: 491
677.    X-FS-Support: update_display,send_info
678.    Remote-Party-ID: "Extension 1000" <sip:1000@139.59.19.72>;party=calling;screen=yes;privacy=off
679.  
680.    v=0
681.    o=Shashi-switch-sdp 1527689106 1527689107 IN IP4 139.59.19.72
682.    s=Shashi-switch-sdp
683.    c=IN IP4 139.59.19.72
684.    t=0 0
685.    m=audio 20616 RTP/AVP 102 103 9 0 8 101
686.    a=rtpmap:102 opus/48000/2
687.    a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
688.    a=rtpmap:103 telephone-event/48000
689.    a=fmtp:103 0-16
690.    a=rtpmap:9 G722/8000
691.    a=rtpmap:0 PCMU/8000
692.    a=rtpmap:8 PCMA/8000
693.    a=rtpmap:101 telephone-event/8000
694.    a=fmtp:101 0-16
695.    a=ptime:20
696.    ------------------------------------------------------------------------
697. send 419 bytes to udp/[139.59.19.72]:5060 at 19:49:40.281520:
698.    ------------------------------------------------------------------------
699.    SIP/2.0 100 Trying
700.    Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKvy3DZp7rFc1vS
701.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
702.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
703.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
704.    CSeq: 123518799 INVITE
705.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
706.    Content-Length: 0
707.  
708.    ------------------------------------------------------------------------
709. 2018-05-30 19:49:40.273085 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [received][100]
710. 2018-05-30 19:49:40.273085 [DEBUG] sofia.c:7301 Remote SDP:
711. v=0
712. o=Shashi-switch-sdp 1527689106 1527689107 IN IP4 139.59.19.72
713. s=Shashi-switch-sdp
714. c=IN IP4 139.59.19.72
715. t=0 0
716. m=audio 20616 RTP/AVP 102 103 9 0 8 101
717. a=rtpmap:102 opus/48000/2
718. a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
719. a=rtpmap:103 telephone-event/48000
720. a=fmtp:103 0-16
721. a=rtpmap:9 G722/8000
722. a=rtpmap:0 PCMU/8000
723. a=rtpmap:8 PCMA/8000
724. a=rtpmap:101 telephone-event/8000
725. a=fmtp:101 0-16
726. a=ptime:20
727.  
728. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[opus:116:48000:20:0:1]
729. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
730. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[G722:9:8000:20:64000:1]
731. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
732. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
733. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5047 Set telephone-event payload to 103@48000
734. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
735. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
736. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
737. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
738. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
739. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
740. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
741. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
742. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
743. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
744. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
745. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
746. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
747. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5131 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
748. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5186 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
749. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5390 Set telephone-event payload to 103@48000
750. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:5448 sofia/external/1000@139.59.19.72 Set 2833 dtmf send payload to 103 recv payload to 103
751. 2018-05-30 19:49:40.273085 [DEBUG] switch_core_media.c:8147 Audio params are unchanged for sofia/external/1000@139.59.19.72.
752. 2018-05-30 19:49:40.273085 [DEBUG] sofia.c:8206 Processing updated SDP
753. send 1049 bytes to udp/[139.59.19.72]:5060 at 19:49:40.282310:
754.    ------------------------------------------------------------------------
755.    SIP/2.0 200 OK
756.    Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bKvy3DZp7rFc1vS
757.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
758.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
759.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
760.    CSeq: 123518799 INVITE
761.    Contact: <sip:gw+record_test@159.89.163.195:5040;transport=udp>
762.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
763.    Accept: application/sdp
764.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
765.    Require: timer
766.    Supported: timer, path, replaces
767.    Session-Expires: 120;refresher=uac
768.    Content-Type: application/sdp
769.    Content-Disposition: session
770.    Content-Length: 305
771.  
772.    v=0
773.    o=FreeSWITCH 1527681426 1527681427 IN IP4 159.89.163.195
774.    s=FreeSWITCH
775.    c=IN IP4 159.89.163.195
776.    t=0 0
777.    m=audio 28298 RTP/AVP 102 103
778.    a=rtpmap:102 opus/48000/2
779.    a=fmtp:102 useinbandfec=1; ptime=20; minptime=10; maxptime=40; stereo=1
780.    a=rtpmap:103 telephone-event/48000
781.    a=fmtp:103 0-16
782.    a=ptime:20
783.    ------------------------------------------------------------------------
784. 2018-05-30 19:49:40.273085 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [completed][200]
785. recv 441 bytes from udp/[139.59.19.72]:5060 at 19:49:40.302574:
786.    ------------------------------------------------------------------------
787.    ACK sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0
788.    Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bKX7v60HrvcNQFN
789.    Max-Forwards: 70
790.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
791.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
792.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
793.    CSeq: 123518799 ACK
794.    Contact: <sip:mod_sofia@139.59.19.72:5060>
795.    Content-Length: 0
796.  
797.    ------------------------------------------------------------------------
798. 2018-05-30 19:49:40.313079 [DEBUG] sofia.c:7291 Channel sofia/external/1000@139.59.19.72 entering state [ready][200]
799. 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
800. 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[411] Bytes encoded[88491] Encoded length ms[8220] Average encoded bitrate bps[88491]
801. 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
802. 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[395] PLC[0] FEC[0]
803. 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
804. 2018-05-30 19:49:46.393081 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
805. 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
806. 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[42] Bytes encoded[7807] Encoded length ms[840] Average encoded bitrate bps[0]
807. 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
808. 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[42] PLC[0] FEC[0]
809. 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
810. 2018-05-30 19:49:47.233087 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
811. 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
812. 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[550] Bytes encoded[121681] Encoded length ms[11000] Average encoded bitrate bps[88495]
813. 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
814. 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[544] PLC[0] FEC[0]
815. 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
816. 2018-05-30 19:49:58.233098 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
817. 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
818. 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[76] Bytes encoded[16898] Encoded length ms[1520] Average encoded bitrate bps[135184]
819. 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
820. 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[76] PLC[0] FEC[0]
821. 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
822. 2018-05-30 19:49:59.753082 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [120000bps]
823. recv 619 bytes from udp/[139.59.19.72]:5060 at 19:50:09.585677:
824.    ------------------------------------------------------------------------
825.    BYE sip:gw+record_test@159.89.163.195:5040;transport=udp SIP/2.0
826.    Via: SIP/2.0/UDP 139.59.19.72;rport;branch=z9hG4bK028g62a73Ft7Q
827.    Max-Forwards: 70
828.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
829.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
830.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
831.    CSeq: 123518800 BYE
832.    User-Agent: Shashi-switch-sip
833.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
834.    Supported: timer, path, replaces
835.    Reason: Q.850;cause=16;text="NORMAL_CLEARING"
836.    Content-Length: 0
837.  
838.    ------------------------------------------------------------------------
839. 2018-05-30 19:50:09.593068 [NOTICE] sofia.c:1079 Hangup sofia/external/1000@139.59.19.72 [CS_EXECUTE] [NORMAL_CLEARING]
840. send 536 bytes to udp/[139.59.19.72]:5060 at 19:50:09.601292:
841.    ------------------------------------------------------------------------
842.    SIP/2.0 200 OK
843.    Via: SIP/2.0/UDP 139.59.19.72;rport=5060;branch=z9hG4bK028g62a73Ft7Q
844.    From: "Extension 1000" <sip:1000@139.59.19.72>;tag=71jX784Kjc7Hr
845.    To: <sip:gw+record_test@159.89.163.195:5040;transport=udp;gw=record_test>;tag=1SXBS74QmHctj
846.    Call-ID: 4c60ac69-dee5-1236-8e8c-3ac62515e22e
847.    CSeq: 123518800 BYE
848.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
849.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
850.    Supported: timer, path, replaces
851.    Content-Length: 0
852.  
853.    ------------------------------------------------------------------------
854. 2018-05-30 19:50:09.593068 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external/1000@139.59.19.72]
855. 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_bridge.c:825 sofia/external/1000@139.59.19.72 ending bridge by request from write function
856. 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/1003@124.123.68.233:10222]
857. 2018-05-30 19:50:09.613060 [NOTICE] switch_ivr_bridge.c:1034 Hangup sofia/internal/1003@124.123.68.233:10222 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
858. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1003@124.123.68.233:10222) State EXCHANGE_MEDIA going to sleep
859. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_HANGUP (Cur 2 Tot 13)
860. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1003@124.123.68.233:10222) Callstate Change ACTIVE -> HANGUP
861. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1003@124.123.68.233:10222) State HANGUP
862. 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:443 sofia/internal/1003@124.123.68.233:10222 Overriding SIP cause 480 with 200 from the other leg
863. 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1003@124.123.68.233:10222 hanging up, cause: NORMAL_CLEARING
864. 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/1003@124.123.68.233:10222
865. send 658 bytes to tcp/[124.123.68.233]:10222 at 19:50:09.618167:
866.    ------------------------------------------------------------------------
867.    BYE sip:1003@124.123.68.233:10222;transport=TCP SIP/2.0
868.    Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKtr3m32Hj804DF
869.    Max-Forwards: 70
870.    From: "Extension 1000" <sip:1000@159.89.163.195>;tag=03e14v3jr65Ua
871.    To: <sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92>;tag=b0260860
872.    Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88
873.    CSeq: 123518799 BYE
874.    User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20180504T143706Z~ed4920e792~64bit
875.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
876.    Supported: timer, path, replaces
877.    Reason: Q.850;cause=16;text="NORMAL_CLEARING"
878.    Content-Length: 0
879.  
880.    ------------------------------------------------------------------------
881. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1003@124.123.68.233:10222 Standard HANGUP, cause: NORMAL_CLEARING
882. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1003@124.123.68.233:10222) State HANGUP going to sleep
883. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1003@124.123.68.233:10222) State Change CS_HANGUP -> CS_REPORTING
884. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_REPORTING (Cur 2 Tot 13)
885. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1003@124.123.68.233:10222) State REPORTING
886. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1003@124.123.68.233:10222 Standard REPORTING, cause: NORMAL_CLEARING
887. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1003@124.123.68.233:10222) State REPORTING going to sleep
888. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1003@124.123.68.233:10222) State Change CS_REPORTING -> CS_DESTROY
889. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_session.c:1713 Session 13 (sofia/internal/1003@124.123.68.233:10222) Locked, Waiting on external entities
890. 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_bridge.c:1846 sofia/external/1000@139.59.19.72 skip receive message [TRANSFER] (channel is hungup already)
891. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_session.c:2885 sofia/external/1000@139.59.19.72 skip receive message [PHONE_EVENT] (channel is hungup already)
892. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1000@139.59.19.72) State EXECUTE going to sleep
893. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_HANGUP (Cur 2 Tot 13)
894. 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_async.c:1324 Stop recording file /usr/local/freeswitch/recordings/2018-05-30-19-48-44_1001_1000.wav
895. 2018-05-30 19:50:09.613060 [DEBUG] switch_ivr_async.c:1388 Channel is hung up
896. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_media_bug.c:1315 Removing BUG from sofia/external/1000@139.59.19.72
897. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:850 (sofia/external/1000@139.59.19.72) Callstate Change ACTIVE -> HANGUP
898. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1000@139.59.19.72) State HANGUP
899. 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:449 Channel sofia/external/1000@139.59.19.72 hanging up, cause: NORMAL_CLEARING
900. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:60 sofia/external/1000@139.59.19.72 Standard HANGUP, cause: NORMAL_CLEARING
901. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1000@139.59.19.72) State HANGUP going to sleep
902. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:619 (sofia/external/1000@139.59.19.72) State Change CS_HANGUP -> CS_REPORTING
903. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@139.59.19.72) Running State Change CS_REPORTING (Cur 2 Tot 13)
904. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1000@139.59.19.72) State REPORTING
905. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:174 sofia/external/1000@139.59.19.72 Standard REPORTING, cause: NORMAL_CLEARING
906. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1000@139.59.19.72) State REPORTING going to sleep
907. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:610 (sofia/external/1000@139.59.19.72) State Change CS_REPORTING -> CS_DESTROY
908. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_session.c:1713 Session 12 (sofia/external/1000@139.59.19.72) Locked, Waiting on external entities
909. 2018-05-30 19:50:09.613060 [NOTICE] switch_core_session.c:1731 Session 12 (sofia/external/1000@139.59.19.72) Ended
910. 2018-05-30 19:50:09.613060 [NOTICE] switch_core_session.c:1735 Close Channel sofia/external/1000@139.59.19.72 [CS_DESTROY]
911. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:741 (sofia/external/1000@139.59.19.72) Running State Change CS_DESTROY (Cur 1 Tot 13)
912. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1000@139.59.19.72) State DESTROY
913. 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:354 sofia/external/1000@139.59.19.72 SOFIA DESTROY
914. 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[450] PLC[0] FEC[0]
915. 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
916. 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
917. 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[493] Bytes encoded[110276] Encoded length ms[9860] Average encoded bitrate bps[98023]
918. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:181 sofia/external/1000@139.59.19.72 Standard DESTROY
919. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1000@139.59.19.72) State DESTROY going to sleep
920. 2018-05-30 19:50:09.613060 [NOTICE] switch_core_session.c:1731 Session 13 (sofia/internal/1003@124.123.68.233:10222) Ended
921. 2018-05-30 19:50:09.613060 [NOTICE] switch_core_session.c:1735 Close Channel sofia/internal/1003@124.123.68.233:10222 [CS_DESTROY]
922. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1003@124.123.68.233:10222) Running State Change CS_DESTROY (Cur 0 Tot 13)
923. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1003@124.123.68.233:10222) State DESTROY
924. 2018-05-30 19:50:09.613060 [DEBUG] mod_sofia.c:354 sofia/internal/1003@124.123.68.233:10222 SOFIA DESTROY
925. 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[3989] PLC[0] FEC[0]
926. 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[79] Bytes encoded[2549] Encoded length ms[1580] Average encoded bitrate bps[20392]
927. 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
928. 2018-05-30 19:50:09.613060 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[3912] Bytes encoded[462071] Encoded length ms[78240] Average encoded bitrate bps[47391]
929. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1003@124.123.68.233:10222 Standard DESTROY
930. 2018-05-30 19:50:09.613060 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1003@124.123.68.233:10222) State DESTROY going to sleep
931. recv 417 bytes from tcp/[124.123.68.233]:10222 at 19:50:09.704040:
932.    ------------------------------------------------------------------------
933.    SIP/2.0 200 OK
934.    Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKtr3m32Hj804DF
935.    Contact: <sip:1003@124.123.68.233:10222;transport=TCP>
936.    To: <sip:1003@124.123.68.233:10222;transport=TCP;rinstance=621965d30a4d4f92>;tag=b0260860
937.    From: "Extension 1000" <sip:1000@159.89.163.195>;tag=03e14v3jr65Ua
938.    Call-ID: 4d71cbb5-dee5-1236-d6a5-528373432f88
939.    CSeq: 123518799 BYE
940.    User-Agent: Z 5.2.14 rv2.8.88
941.    Content-Length: 0
942.  
943.    ------------------------------------------------------------------------
944. freeswitch@debian-s-1vcpu-1gb-blr1-01> ...
945.