1.  
2.  
3.  
4.  
5.  
6.  
7.  
8.  
9.  
10.  
11.  
12.  
13.  
14.  
15.  
16.  
17.  
18.  
19.  
20.  
21.  
22.  
23.  
24.  
25.  
26.  
27.  
28.  
29.  
30.  
31.  
32.  
33.  
34.  
35.  
36.  
37.  
38.  
39.  
40.  
41.  
42.  
43.  
44.  
45.  
46.  
47.  
48.  
49.  
50.  
51.  
52.  
53.  
54.  
55.  
56.  
57.  
58.  
59.  
60.  
61.  
62.  
63.  
64.  
65.  
66.  
67.  
68.  
69.  
70.  
71.  
72.  
73.  
74.  
75.  
76.  
77.  
78.  
79.  
80.  
81.  
82.  
83.  
84.  
85.  
86.  
87.  
88.  
89.  
90.  
91.  
92.  
93.  
94.  
95.  
96.  
97.  
98.  
99.  
100.  
101.  
102.  
103.  
104.  
105.  
106.  
107.  
108.  
109.  
110.  
111.  
112.  
113.  
114.  
115.  
116.  
117.  
118.  
119.  
120.  
121.  
122.  
123.  
124.  
125.  
126.  
127.  
128.  
129.  
130.  
131.  
132.  
133.  
134.  
135.  
136.  
137.  
138.  
139.  
140.  
141.  
142.  
143.  
144.  
145.  
146.  
147.  
148.  
149.  
150.  
151.  
152.  
153.  
154.  
155.  
156.  
157.  
158.  
159.  
160.  
161.  
162.  
163.  
164.  
165.  
166.  
167.  
168.  
169.  
170.  
171.  
172.  
173.  
174.  
175.  
176.  
177.  
178.  
179.  
180.  
181.  
182.  
183.  
184.  
185.  
186.  
187.  
188.  
189.  
190.  
191.  
192.  
193.  
194.  
195.  
196.  
197.  
198.  
199.  
200.  
201.  
202.  
203.  
204.  
205.  
206.  
207.  
208.  
209. EXECUTE sofia/internal/pop@faith.ski set(voicemail_profile=default)
210. 2016-08-05 23:55:28.118149 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [voicemail_profile]=[default]
211. EXECUTE sofia/internal/pop@faith.ski lua(app.lua voicemail)
212. 2016-08-05 23:55:28.118149 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x810ded0f0 Connected.
213. 2016-08-05 23:55:28.141284 [DEBUG] mod_sofia.c:789 Disabling proxy mode due to call answer with no bridge
214. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
215. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
216. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
217. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1]
218. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4420 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match
219. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
220. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
221. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
222. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4420 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
223. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
224. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
225. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
226. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
227. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
228. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
229. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4420 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
230. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
231. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
232. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
233. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4420 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
234. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
235. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
236. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
237. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
238. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4281 Set telephone-event payload to 101@8000
239. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:3091 Set Codec sofia/internal/pop@faith.ski GSM/8000 20 ms 160 samples 13200 bits 1 channels
240. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_codec.c:111 sofia/internal/pop@faith.ski Original read codec set to GSM:3
241. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4634 Set telephone-event payload to 101@8000
242. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4693 sofia/internal/pop@faith.ski Set 2833 dtmf send payload to 101 recv payload to 101
243. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:6496 AUDIO RTP [sofia/internal/pop@faith.ski] 45.32.188.45 port 32448 -> 49.183.185.185 port 23804 codec: 3 ms: 20
244. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms
245. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]: START SESSION INITIALIZATION. sID=0.
246. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]: ZID=326432306263326430343865.
247. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]: Loading User's profile:
248. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:    allowclear: OFF
249. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:    autosecure: ON
250. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:  disclose_bit: OFF
251. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:  signal. role: Unknown
252. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:           TTL: 4294967295
253. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:   SAS schemes:
254. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 B256
255. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 B32  
256. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439
257. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:      Ciphers:
258. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 AES3
259. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 AES1
260. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439
261. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:    PK schemes:
262. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 EC25
263. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 DH3k
264. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 DH2k
265. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 Mult
266. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439
267. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:           ATL:
268. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 HS32
269. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 HS80
270. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439
271. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:       Hashes:
272. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 S256
273. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439
274. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]: Session initialization - DONE. sID=0.
275.  
276. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]: ATTACH NEW STREAM to sID=0:
277. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [        zrtp]:   Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>.
278. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:   Empty slot was found - initializing new stream with ID=0.
279. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]:   Preparing ZRTP Hello according to the Session profile.
280. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp main]: ATTACH NEW STREAM - DONE.
281. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [   zrtp mitm]: START REGISTRATION STREAM ID=0 mode=CLEAR state=ACTIVE.
282. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [ zrtp engine]: START STREAM ID=0 mode=CLEAR state=ACTIVE.
283. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [        zrtp]:   Stream ID=0 CLEAR switching <ACTIVE> ---> <START>.
284. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52228 size=148. Stream 0:CLEAR:START
285. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:6795 sofia/internal/pop@faith.ski Set 2833 dtmf send payload to 101
286. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:6802 sofia/internal/pop@faith.ski Set 2833 dtmf receive payload to 101
287. 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:6825 sofia/internal/pop@faith.ski Set rtp dtmf delay to 40
288. 2016-08-05 23:55:28.141284 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/pop@faith.ski!
289. 2016-08-05 23:55:28.141284 [DEBUG] switch_channel.c:3471 (sofia/internal/pop@faith.ski) Callstate Change RINGING -> EARLY
290. 2016-08-05 23:55:28.141284 [DEBUG] mod_sofia.c:821 Local SDP sofia/internal/pop@faith.ski:
291. v=0
292. o=FreeSWITCH 1470372880 1470372881 IN IP4 45.32.188.45
293. s=FreeSWITCH
294. c=IN IP4 45.32.188.45
295. t=0 0
296. m=audio 32448 RTP/AVP 3 101
297. a=rtpmap:3 GSM/8000
298. a=rtpmap:101 telephone-event/8000
299. a=fmtp:101 0-16
300. a=ptime:20
301. a=sendrecv
302.  
303. 2016-08-05 23:55:28.141284 [NOTICE] switch_cpp.cpp:686 Channel [sofia/internal/pop@faith.ski] has been answered
304. 2016-08-05 23:55:28.141284 [DEBUG] switch_channel.c:3770 (sofia/internal/pop@faith.ski) Callstate Change EARLY -> ACTIVE
305. EXECUTE sofia/internal/pop@faith.ski unbind_meta_app()
306. 2016-08-05 23:55:28.141284 [INFO] switch_ivr_async.c:4065 UnBound A-Leg: ALL
307. 2016-08-05 23:55:28.141284 [DEBUG] switch_cpp.cpp:746 CoreSession::setVariable('playback_terminators', '#')
308. send 1058 bytes to udp/[49.183.185.185]:23510 at 23:55:28.161660:
309.    ------------------------------------------------------------------------
310.    SIP/2.0 200 OK
311.    Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---34d5b403f7e06f91;rport=23510
312.    From: <sip:pop@faith.ski;transport=UDP>;tag=cf1c7915
313.    To: <sip:masked@faith.ski;transport=UDP>;tag=B6vpNmmXDajmg
314.    Call-ID: sWT2NxFucFKcIp0KDE9ivQ..
315.    CSeq: 2 INVITE
316.    Contact: <sip:masked@45.32.188.45:5060;transport=udp>
317.    User-Agent: FreeSWITCH
318.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
319.    Supported: timer, path, replaces
320.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
321.    Content-Type: application/sdp
322.    Content-Disposition: session
323.    Content-Length: 219
324.    Remote-Party-ID: "masked" <sip:masked@faith.ski>;party=calling;privacy=off;screen=no
325.    
326.    v=0
327.    o=FreeSWITCH 1470372880 1470372881 IN IP4 45.32.188.45
328.    s=FreeSWITCH
329.    c=IN IP4 45.32.188.45
330.    t=0 0
331.    m=audio 32448 RTP/AVP 3 101
332.    a=rtpmap:3 GSM/8000
333.    a=rtpmap:101 telephone-event/8000
334.    a=fmtp:101 0-16
335.    a=ptime:20
336.    ------------------------------------------------------------------------
337. EXECUTE sofia/internal/pop@faith.ski playback(silence_stream://200)
338. 2016-08-05 23:55:28.161816 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
339. 2016-08-05 23:55:28.161816 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [completed][200]
340. 2016-08-05 23:55:28.217780 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52229 size=148. Stream 0:CLEAR:START
341. 2016-08-05 23:55:28.317601 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52230 size=148. Stream 0:CLEAR:START
342. 2016-08-05 23:55:28.337974 [DEBUG] switch_ivr_play_say.c:1910 done playing file silence_stream://200
343. 2016-08-05 23:55:28.337974 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
344. recv 429 bytes from udp/[49.183.185.185]:23510 at 23:55:28.343470:
345.    ------------------------------------------------------------------------
346.    ACK sip:masked@45.32.188.45:5060;transport=udp SIP/2.0
347.    Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---bceeb08953c12a58;rport
348.    Max-Forwards: 70
349.    Contact: <sip:pop@49.183.185.185:23510;transport=UDP>
350.    To: <sip:masked@faith.ski;transport=UDP>;tag=B6vpNmmXDajmg
351.    From: <sip:pop@faith.ski;transport=UDP>;tag=cf1c7915
352.    Call-ID: sWT2NxFucFKcIp0KDE9ivQ..
353.    CSeq: 2 ACK
354.    User-Agent: Zoiper r55b5166
355.    Content-Length: 0
356.    
357.    ------------------------------------------------------------------------
358. 2016-08-05 23:55:28.357524 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [ready][200]
359. 2016-08-05 23:55:28.538164 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52231 size=148. Stream 0:CLEAR:START
360. 2016-08-05 23:55:28.717658 [DEBUG] switch_rtp.c:6711 Correct audio ip/port confirmed.
361. 2016-08-05 23:55:28.758112 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52232 size=148. Stream 0:CLEAR:START
362. 2016-08-05 23:55:28.978164 [DEBUG] switch_rtp.c:1439  [ zrtp engine]: WARNING! HELLO have been resent 5 times without a response. Raising ZRTP_EVENT_NO_ZRTP_QUICK event. ID=0
363. 2016-08-05 23:55:28.978164 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52233 size=148. Stream 0:CLEAR:START
364. 2016-08-05 23:55:29.198104 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52234 size=148. Stream 0:CLEAR:START
365. 2016-08-05 23:55:29.417498 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52235 size=148. Stream 0:CLEAR:START
366. 2016-08-05 23:55:29.637457 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52236 size=148. Stream 0:CLEAR:START
367. 2016-08-05 23:55:29.698125 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
368. 2016-08-05 23:55:29.698125 [DEBUG] switch_ivr.c:3553 No language specified - Using [en]
369. 2016-08-05 23:55:29.698125 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
370. 2016-08-05 23:55:29.858139 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52237 size=148. Stream 0:CLEAR:START
371. 2016-08-05 23:55:30.058211 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52238 size=148. Stream 0:CLEAR:START
372. 2016-08-05 23:55:30.278168 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52239 size=148. Stream 0:CLEAR:START
373. 2016-08-05 23:55:30.498095 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52240 size=148. Stream 0:CLEAR:START
374. 2016-08-05 23:55:30.698154 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52241 size=148. Stream 0:CLEAR:START
375. 2016-08-05 23:55:30.898180 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52242 size=148. Stream 0:CLEAR:START
376. 2016-08-05 23:55:31.118148 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52243 size=148. Stream 0:CLEAR:START
377. 2016-08-05 23:55:31.338178 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52244 size=148. Stream 0:CLEAR:START
378. 2016-08-05 23:55:31.537336 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52245 size=148. Stream 0:CLEAR:START
379. 2016-08-05 23:55:31.738179 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52246 size=148. Stream 0:CLEAR:START
380. 2016-08-05 23:55:31.878063 [DEBUG] switch_ivr_play_say.c:1910 done playing file file_string://digits/6.wav!digits/9.wav!digits/6.wav!digits/9.wav
381. 2016-08-05 23:55:31.878063 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
382. 2016-08-05 23:55:31.938027 [DEBUG] switch_rtp.c:1439  [  zrtp utils]:   Send <HELLO> ssrc=1752845048 seq=52247 size=148. Stream 0:CLEAR:START
383. 2016-08-05 23:55:32.158113 [DEBUG] switch_rtp.c:1439  [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=0
384. 2016-08-05 23:55:32.158113 [DEBUG] switch_rtp.c:1439  [        zrtp]:   Stream ID=0 CLEAR switching <START> ---> <NOZRTP>.
385. 2016-08-05 23:55:32.858192 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav
386. 2016-08-05 23:55:33.078135 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
387. 2016-08-05 23:55:33.078135 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
388. 2016-08-05 23:55:37.678108 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav
389. 2016-08-05 23:55:37.778113 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
390. 2016-08-05 23:55:38.798113 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
391. 2016-08-05 23:55:38.798113 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
392. 2016-08-05 23:55:39.797960 [DEBUG] switch_ivr_play_say.c:1910 done playing file tone_stream://L=1;%(1000, 0, 640)
393. 2016-08-05 23:55:39.898109 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
394. 2016-08-05 23:55:39.898109 [DEBUG] switch_ivr_play_say.c:559 Raw Codec Activated, ready to waste resources!
395. 2016-08-05 23:55:39.898109 [DEBUG] switch_ivr_play_say.c:673 Raw Codec Activated
396. 2016-08-05 23:55:39.898109 [DEBUG] switch_core_codec.c:221 sofia/internal/pop@faith.ski Push codec L16:100
397. 2016-08-05 23:55:44.897304 [DEBUG] switch_core_codec.c:246 sofia/internal/pop@faith.ski Restore previous codec GSM:3.
398. 2016-08-05 23:55:44.897304 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
399. 2016-08-05 23:55:46.118137 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-listen_to_recording.wav
400. 2016-08-05 23:55:46.118137 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
401. 2016-08-05 23:55:46.518203 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav
402. 2016-08-05 23:55:46.518203 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
403. 2016-08-05 23:55:46.978077 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/1.wav
404. 2016-08-05 23:55:47.098101 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
405. 2016-08-05 23:55:47.098101 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
406. 2016-08-05 23:55:48.238060 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-save_recording.wav
407. 2016-08-05 23:55:48.238060 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
408. 2016-08-05 23:55:48.637311 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav
409. 2016-08-05 23:55:48.637311 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
410. 2016-08-05 23:55:49.038138 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/2.wav
411. 2016-08-05 23:55:49.158172 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
412. 2016-08-05 23:55:49.158172 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
413. 2016-08-05 23:55:50.038028 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-rerecord.wav
414. 2016-08-05 23:55:50.038028 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
415. 2016-08-05 23:55:50.438135 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav
416. 2016-08-05 23:55:50.438135 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
417. 2016-08-05 23:55:50.838181 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/3.wav
418. 2016-08-05 23:55:53.858111 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
419. 2016-08-05 23:55:53.858111 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
420. 2016-08-05 23:55:55.078077 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-listen_to_recording.wav
421. 2016-08-05 23:55:55.078077 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
422. 2016-08-05 23:55:55.478150 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav
423. 2016-08-05 23:55:55.478150 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
424. 2016-08-05 23:55:55.938123 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/1.wav
425. 2016-08-05 23:55:56.038126 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
426. 2016-08-05 23:55:56.038126 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
427. send 881 bytes to tls/[119.9.12.222]:5061 at 23:55:56.042048:
428.    ------------------------------------------------------------------------
429.    REGISTER sip:sip.au.didlogic.net;transport=tls SIP/2.0
430.    Via: SIP/2.0/TLS 45.32.188.45:5081;rport;branch=z9hG4bK32yKB6Nym1m4H
431.    Max-Forwards: 70
432.    From: <sip:19423@sip.au.didlogic.net>;tag=te8cNUUj3reyH
433.    To: <sip:19423@sip.au.didlogic.net>
434.    Call-ID: f04031ee-0a5b-e611-a0a3-8f57d09e751d
435.    CSeq: 94864615 REGISTER
436.    Contact: <sip:19423@45.32.188.45:5081;transport=tls;transport=tls;gw=12e36ae0-b768-4707-acd5-3b91d228c59a>
437.    Expires: 800
438.    User-Agent: FreeSWITCH
439.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
440.    Supported: timer, path, replaces
441.    Authorization: Digest username="19423", realm="sip.au.didlogic.net", nonce="V6SbQlekmhaDSa/iG8A5EHii4f6993FtSYNer4A=", cnonce="xnRLgdWtEjS4mMfaZ2pXZA", algorithm=MD5, uri="sip:sip.au.didlogic.net;transport=tls", response="801a493246aa7c757801079e5d18c52b", qop=auth, nc=00000014
442.    Content-Length: 0
443.    
444.    ------------------------------------------------------------------------
445. recv 511 bytes from tls/[119.9.12.222]:5061 at 23:55:56.069758:
446.    ------------------------------------------------------------------------
447.    SIP/2.0 200 OK
448.    Via: SIP/2.0/TLS 45.32.188.45:5081;rport=41810;branch=z9hG4bK32yKB6Nym1m4H;received=45.32.188.45
449.    From: <sip:19423@sip.au.didlogic.net>;tag=te8cNUUj3reyH
450.    To: <sip:19423@sip.au.didlogic.net>;tag=b27e1a1d33761e85846fc98f5f3a7e58.82f2
451.    Call-ID: f04031ee-0a5b-e611-a0a3-8f57d09e751d
452.    CSeq: 94864615 REGISTER
453.    Contact: <sip:19423@45.32.188.45:5081;transport=tls;transport=tls;gw=12e36ae0-b768-4707-acd5-3b91d228c59a>;expires=800;received="sip:45.32.188.45:41810;transport=TLS"
454.    Content-Length: 0
455.    
456.    ------------------------------------------------------------------------
457. 2016-08-05 23:55:57.176991 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-save_recording.wav
458. 2016-08-05 23:55:57.176991 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
459. 2016-08-05 23:55:57.577762 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav
460. 2016-08-05 23:55:57.577762 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
461. 2016-08-05 23:55:57.978220 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/2.wav
462. 2016-08-05 23:55:58.098148 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf:
463. 2016-08-05 23:55:58.098148 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
464. recv 427 bytes from udp/[163.172.202.74]:5061 at 23:55:58.633128:
465.    ------------------------------------------------------------------------
466.    REGISTER sip:45.32.188.45:5060 SIP/2.0
467.    Via: SIP/2.0/UDP 163.172.202.74:5061;branch=z9hG4bK406631864a3021ed57a49a8d;rport
468.    From: "2314" <sip:2314@45.32.188.45:5060>;tag=406631864a4ef
469.    To: "2314" <sip:2314@45.32.188.45:5060>
470.    Call-ID: 1864a302-59a01ed-57a49a8d@45.32.188.45
471.    CSeq: 1 REGISTER
472.    Contact: "2314" <sip:2314@163.172.202.74:5061>
473.    User-Agent: VaxSIPUserAgent/3.1
474.    Expires: 1800
475.    Max-Forwards: 70
476.    Content-Length: 0
477.    
478.    ------------------------------------------------------------------------
479. 2016-08-05 23:55:58.618124 [WARNING] sofia_reg.c:1787 SIP auth challenge (REGISTER) on sofia profile 'internal' for [2314@45.32.188.45] from ip 163.172.202.74
480. send 610 bytes to udp/[163.172.202.74]:5061 at 23:55:58.634999:
481.    ------------------------------------------------------------------------
482.    SIP/2.0 401 Unauthorized
483.    Via: SIP/2.0/UDP 163.172.202.74:5061;branch=z9hG4bK406631864a3021ed57a49a8d;rport=5061
484.    From: "2314" <sip:2314@45.32.188.45:5060>;tag=406631864a4ef
485.    To: "2314" <sip:2314@45.32.188.45:5060>;tag=S4yHeF0e569Sj
486.    Call-ID: 1864a302-59a01ed-57a49a8d@45.32.188.45
487.    CSeq: 1 REGISTER
488.    User-Agent: FreeSWITCH
489.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
490.    Supported: timer, path, replaces
491.    WWW-Authenticate: Digest realm="45.32.188.45", nonce="d0dd4656-145b-e611-a0a3-8f57d09e751d", algorithm=MD5, qop="auth"
492.    Content-Length: 0
493.    
494.    ------------------------------------------------------------------------
495. 2016-08-05 23:55:58.977376 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-rerecord.wav
496. 2016-08-05 23:55:58.977376 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
497. recv 660 bytes from udp/[163.172.202.74]:5061 at 23:55:59.005775:
498.    ------------------------------------------------------------------------
499.    REGISTER sip:45.32.188.45:5060 SIP/2.0
500.    Via: SIP/2.0/UDP 163.172.202.74:5061;branch=z9hG4bK406641864a4781f057a49a8e;rport
501.    From: "2314" <sip:2314@45.32.188.45:5060>;tag=406641864a668
502.    To: "2314" <sip:2314@45.32.188.45:5060>
503.    Call-ID: 1864a302-59a01ed-57a49a8d@45.32.188.45
504.    CSeq: 2 REGISTER
505.    Contact: "2314" <sip:2314@163.172.202.74:5061>
506.    Authorization: Digest username="2314", realm="45.32.188.45", nonce="d0dd4656-145b-e611-a0a3-8f57d09e751d", uri="sip:45.32.188.45", response="439507879752bb5999a3e395a7792424", algorithm=MD5, cnonce="1864a478", qop=auth, nc=00000002
507.    User-Agent: VaxSIPUserAgent/3.1
508.    Expires: 1800
509.    Max-Forwards: 70
510.    Content-Length: 0
511.    
512.    ------------------------------------------------------------------------
513. 2016-08-05 23:55:58.998221 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x808df70f0 Connected.
514. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x810e7a0f0 Connected.
515. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x810e7a0f0 released.
516. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x810e7a0f0 Connected.
517. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x810e7a0f0 released.
518. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x808df70f0 released.
519. 2016-08-05 23:55:59.018886 [WARNING] sofia_reg.c:2901 Can't find user [2314@45.32.188.45] from 163.172.202.74
520. You must define a domain called '45.32.188.45' in your directory and add a user with the id="2314" attribute
521. and you must configure your device to use the proper domain in it's authentication credentials.
522. 2016-08-05 23:55:59.018886 [WARNING] sofia_reg.c:1732 SIP auth failure (REGISTER) on sofia profile 'internal' for [2314@45.32.188.45] from ip 163.172.202.74
523. send 487 bytes to udp/[163.172.202.74]:5061 at 23:55:59.024255:
524.    ------------------------------------------------------------------------
525.    SIP/2.0 403 Forbidden
526.    Via: SIP/2.0/UDP 163.172.202.74:5061;branch=z9hG4bK406641864a4781f057a49a8e;rport=5061
527.    From: "2314" <sip:2314@45.32.188.45:5060>;tag=406641864a668
528.    To: "2314" <sip:2314@45.32.188.45:5060>;tag=tDragaHj2F0ce
529.    Call-ID: 1864a302-59a01ed-57a49a8d@45.32.188.45
530.    CSeq: 2 REGISTER
531.    User-Agent: FreeSWITCH
532.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
533.    Supported: timer, path, replaces
534.    Content-Length: 0
535.    
536.    ------------------------------------------------------------------------
537. 2016-08-05 23:55:59.378073 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav
538. 2016-08-05 23:55:59.378073 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
539. 2016-08-05 23:55:59.778129 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/3.wav
540. freeswitch@sip>
541. [sip][      0-$ csh  (1*$ csh)  2$ csh  3$ csh  4$ csh      ][08/05/16 11:56 PM]
542. 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_all_destination]=[UNDEF]
543. EXECUTE sofia/internal/pop@faith.ski set(forward_busy_enabled=)
544. 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_busy_enabled]=[UNDEF]
545. EXECUTE sofia/internal/pop@faith.ski set(forward_busy_destination=)
546. 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_busy_destination]=[UNDEF]
547. EXECUTE sofia/internal/pop@faith.ski set(forward_no_answer_enabled=)
548. 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_no_answer_enabled]=[UNDEF]
549. EXECUTE sofia/internal/pop@faith.ski set(forward_no_answer_destination=)
550. 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_no_answer_destination]=[UNDEF]
551. EXECUTE sofia/internal/pop@faith.ski set(forward_user_not_registered_enabled=)
552. 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_user_not_registered_enabled]=[UNDEF]
553. EXECUTE sofia/internal/pop@faith.ski set(forward_user_not_registered_destination=)
554. 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_user_not_registered_destination]=[UNDEF]
555. EXECUTE sofia/internal/pop@faith.ski set(do_not_disturb=)
556. 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [do_not_disturb]=[UNDEF]
557. EXECUTE sofia/internal/pop@faith.ski set(call_timeout=30)
558. 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [call_timeout]=[30]
559. EXECUTE sofia/internal/pop@faith.ski set(missed_call_app=)
560. 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [missed_call_app]=[UNDEF]
561. EXECUTE sofia/internal/pop@faith.ski set(missed_call_data=)
562. 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [missed_call_data]=[UNDEF]
563. EXECUTE sofia/internal/pop@faith.ski set(call_direction=local)
564. 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [call_direction]=[local]
565. EXECUTE sofia/internal/pop@faith.ski export(origination_callee_id_name=masked)
566. 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[masked]
567. EXECUTE sofia/internal/pop@faith.ski set(RFC2822_DATE=Fri, 05 Aug 2016 23:56:49 +1000)
568. 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [RFC2822_DATE]=[Fri, 05 Aug 2016 23:56:49 +1000]
569. EXECUTE sofia/internal/pop@faith.ski hash(insert/faith.ski-last_dial/pop/masked)
570. EXECUTE sofia/internal/pop@faith.ski eval(not_secure)
571. EXECUTE sofia/internal/pop@faith.ski limit(hash faith.ski masked 5 )
572. 2016-08-05 23:56:49.978050 [DEBUG] switch_limit.c:126 incr called: faith.ski_masked max:5, interval:0
573. 2016-08-05 23:56:49.978050 [DEBUG] mod_hash.c:196 Usage for faith.ski_masked is now 1/5
574. EXECUTE sofia/internal/pop@faith.ski bind_digit_action(local,*1,exec:execute_extension,dx XML faith.ski,both)
575. 2016-08-05 23:56:49.978050 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'local'
576. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *1/local/0 callback: 0x80b014dd0 data: 0x808d07728
577. 2016-08-05 23:56:49.978050 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'local'
578. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *1/local/0 callback: 0x80b014dd0 data: 0x808d07798
579. EXECUTE sofia/internal/pop@faith.ski bind_digit_action(local,*2,exec:record_session,/usr/local/freeswitch/recordings/faith.ski/archive/2016/Aug/05/7728a874-145b-e611-a0a3-8f57d09e751d.wav,both)
580. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *2/local/0 callback: 0x80b014dd0 data: 0x808d079d0
581. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *2/local/0 callback: 0x80b014dd0 data: 0x808d07a90
582. EXECUTE sofia/internal/pop@faith.ski bind_digit_action(local,*3,exec:execute_extension,cf XML faith.ski,both)
583. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *3/local/0 callback: 0x80b014dd0 data: 0x808d07c10
584. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *3/local/0 callback: 0x80b014dd0 data: 0x808d07c80
585. EXECUTE sofia/internal/pop@faith.ski bind_digit_action(local,*4,exec:execute_extension,att_xfer XML faith.ski,both)
586. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *4/local/0 callback: 0x80b014dd0 data: 0x808d07dc0
587. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *4/local/0 callback: 0x80b014dd0 data: 0x808d07e30
588. EXECUTE sofia/internal/pop@faith.ski digit_action_set_realm(local)
589. 2016-08-05 23:56:49.978050 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'local'
590. EXECUTE sofia/internal/pop@faith.ski set(hangup_after_bridge=true)
591. 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [hangup_after_bridge]=[true]
592. EXECUTE sofia/internal/pop@faith.ski set(continue_on_fail=true)
593. 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [continue_on_fail]=[true]
594. EXECUTE sofia/internal/pop@faith.ski hash(insert/faith.ski-call_return/masked/pop)
595. EXECUTE sofia/internal/pop@faith.ski hash(insert/faith.ski-last_dial_ext/masked/7728a874-145b-e611-a0a3-8f57d09e751d)
596. EXECUTE sofia/internal/pop@faith.ski set(called_party_call_group=)
597. 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [called_party_call_group]=[UNDEF]
598. EXECUTE sofia/internal/pop@faith.ski hash(insert/faith.ski-last_dial//7728a874-145b-e611-a0a3-8f57d09e751d)
599. EXECUTE sofia/internal/pop@faith.ski set(api_hangup_hook=lua app.lua hangup)
600. 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [api_hangup_hook]=[lua app.lua hangup]
601. EXECUTE sofia/internal/pop@faith.ski bridge(user/masked@faith.ski)
602. 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [domain_name]=[faith.ski] to event
603. 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [dialed_extension]=[masked] to event
604. 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [origination_callee_id_name]=[masked] to event
605. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables
606. 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [domain_name]=[faith.ski] to event
607. 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [dialed_extension]=[masked] to event
608. 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [origination_callee_id_name]=[masked] to event
609. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables
610. 2016-08-05 23:56:49.978050 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/masked@1.152.97.29:6517 [17a6e374-145b-e611-a0a3-8f57d09e751d]
611. 2016-08-05 23:56:49.978050 [DEBUG] mod_sofia.c:4757 (sofia/internal/masked@1.152.97.29:6517) State Change CS_NEW -> CS_INIT
612. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/masked@1.152.97.29:6517) Running State Change CS_INIT
613. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/masked@1.152.97.29:6517) State INIT
614. 2016-08-05 23:56:49.978050 [DEBUG] mod_sofia.c:89 sofia/internal/masked@1.152.97.29:6517 SOFIA INIT
615. 2016-08-05 23:56:49.978050 [DEBUG] sofia_glue.c:1257 sofia/internal/masked@1.152.97.29:6517 sending invite version: 1.7.0 git ce087fc 2016-06-23 21:07:31Z 64bit
616. Local SDP:
617. v=0
618. o=Zoiper 0 0 IN IP4 49.183.185.185
619. s=Zoiper
620. c=IN IP4 49.183.185.185
621. t=0 0
622. m=audio 23808 RTP/AVP 3 0 8 9 101
623. a=rtpmap:3 GSM/8000
624. a=rtpmap:0 PCMU/8000
625. a=rtpmap:8 PCMA/8000
626. a=rtpmap:9 G722/8000
627. a=rtpmap:101 telephone-event/8000
628. a=fmtp:101 0-16
629.  
630. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:40 sofia/internal/masked@1.152.97.29:6517 Standard INIT
631. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/masked@1.152.97.29:6517) State Change CS_INIT -> CS_ROUTING
632. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/masked@1.152.97.29:6517) State INIT going to sleep
633. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/masked@1.152.97.29:6517) Running State Change CS_ROUTING
634. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/masked@1.152.97.29:6517) State ROUTING
635. 2016-08-05 23:56:49.978050 [DEBUG] mod_sofia.c:142 sofia/internal/masked@1.152.97.29:6517 SOFIA ROUTING
636. 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/masked@1.152.97.29:6517) State Change CS_ROUTING -> CS_CONSUME_MEDIA
637. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/masked@1.152.97.29:6517) State ROUTING going to sleep
638. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/masked@1.152.97.29:6517) Running State Change CS_CONSUME_MEDIA
639. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/masked@1.152.97.29:6517) State CONSUME_MEDIA
640. 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/masked@1.152.97.29:6517) State CONSUME_MEDIA going to sleep
641. send 1246 bytes to udp/[1.152.97.29]:6517 at 23:56:49.994759:
642.    ------------------------------------------------------------------------
643.    INVITE sip:masked@1.152.97.29:6517;transport=UDP;rinstance=9418840bbb26689f SIP/2.0
644.    Via: SIP/2.0/UDP 45.32.188.45;rport;branch=z9hG4bKFZHF1Uv6yea6j
645.    Max-Forwards: 69
646.    From: "pop" <sip:pop@faith.ski>;tag=9mKya0D7pNe5B
647.    To: <sip:masked@1.152.97.29:6517;transport=UDP;rinstance=9418840bbb26689f>
648.    Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764
649.    CSeq: 94866640 INVITE
650.    Contact: <sip:mod_sofia@45.32.188.45:5060>
651.    User-Agent: FreeSWITCH
652.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
653.    Supported: timer, path, replaces
654.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
655.    Content-Type: application/sdp
656.    Content-Disposition: session
657.    Content-Length: 293
658.    X-FS-Support: update_display,send_info
659.    Remote-Party-ID: "pop" <sip:pop@faith.ski>;party=calling;screen=yes;privacy=off
660.    
661.    v=0
662.    o=Zoiper 4357671033347185306 4173376853073507121 IN IP4 49.183.185.185
663.    s=Zoiper
664.    c=IN IP4 49.183.185.185
665.    t=0 0
666.    m=audio 23808 RTP/AVP 3 0 8 9 101
667.    a=rtpmap:3 GSM/8000
668.    a=rtpmap:0 PCMU/8000
669.    a=rtpmap:8 PCMA/8000
670.    a=rtpmap:9 G722/8000
671.    a=rtpmap:101 telephone-event/8000
672.    a=fmtp:101 0-16
673.    ------------------------------------------------------------------------
674. 2016-08-05 23:56:49.978050 [DEBUG] sofia.c:6939 Channel sofia/internal/masked@1.152.97.29:6517 entering state [calling][0]
675. recv 308 bytes from udp/[1.152.97.29]:6517 at 23:56:50.957057:
676.    ------------------------------------------------------------------------
677.    SIP/2.0 100 Trying
678.    Via: SIP/2.0/UDP 45.32.188.45;rport=5060;branch=z9hG4bKFZHF1Uv6yea6j
679.    To: <sip:masked@1.152.97.29:6517;transport=UDP;rinstance=9418840bbb26689f>
680.    From: "pop" <sip:pop@faith.ski>;tag=9mKya0D7pNe5B
681.    Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764
682.    CSeq: 94866640 INVITE
683.    Content-Length: 0
684.    
685.    ------------------------------------------------------------------------
686. recv 441 bytes from udp/[1.152.97.29]:6517 at 23:56:51.157978:
687.    ------------------------------------------------------------------------
688.    SIP/2.0 180 Ringing
689.    Via: SIP/2.0/UDP 45.32.188.45;rport=5060;branch=z9hG4bKFZHF1Uv6yea6j
690.    Contact: <sip:masked@1.152.97.29:6517;transport=UDP>
691.    To: <sip:masked@1.152.97.29:6517;transport=UDP;rinstance=9418840bbb26689f>;tag=81efd82f
692.    From: "pop" <sip:pop@faith.ski>;tag=9mKya0D7pNe5B
693.    Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764
694.    CSeq: 94866640 INVITE
695.    User-Agent: Zoiper r55b5166
696.    Allow-Events: presence, kpml, talk
697.    Content-Length: 0
698.    
699.    ------------------------------------------------------------------------
700. 2016-08-05 23:56:51.157074 [DEBUG] sofia.c:6939 Channel sofia/internal/masked@1.152.97.29:6517 entering state [proceeding][180]
701. 2016-08-05 23:56:51.157074 [NOTICE] sofia.c:7047 Ring-Ready sofia/internal/masked@1.152.97.29:6517!
702. 2016-08-05 23:56:51.157074 [DEBUG] switch_channel.c:3343 (sofia/internal/masked@1.152.97.29:6517) Callstate Change DOWN -> RINGING
703. 2016-08-05 23:56:51.157074 [NOTICE] mod_sofia.c:2220 Ring-Ready sofia/internal/pop@faith.ski!
704. 2016-08-05 23:56:51.157074 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/internal/pop@faith.ski!
705. send 806 bytes to udp/[49.183.185.185]:23510 at 23:56:51.166333:
706.    ------------------------------------------------------------------------
707.    SIP/2.0 180 Ringing
708.    Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---0415a7d6262ece37;rport=23510
709.    From: <sip:pop@faith.ski;transport=UDP>;tag=6be5232a
710.    To: <sip:masked@faith.ski;transport=UDP>;tag=8Bt584v3Scrjg
711.    Call-ID: KUzX0zgTmklc6ZVhY5TgKw..
712.    CSeq: 2 INVITE
713.    Contact: <sip:masked@45.32.188.45:5060;transport=udp>
714.    User-Agent: FreeSWITCH
715.    Accept: application/sdp
716.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
717.    Supported: timer, path, replaces
718.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
719.    Content-Length: 0
720.    Remote-Party-ID: "masked" <sip:masked@faith.ski>;party=calling;privacy=off;screen=no
721.    
722.    ------------------------------------------------------------------------
723. 2016-08-05 23:56:51.177059 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [early][180]
724. recv 917 bytes from udp/[1.152.97.29]:6517 at 23:56:52.780212:
725.    ------------------------------------------------------------------------
726.    SIP/2.0 200 OK
727.    Via: SIP/2.0/UDP 45.32.188.45;rport=5060;branch=z9hG4bKFZHF1Uv6yea6j
728.    Contact: <sip:masked@1.152.97.29:6517;transport=UDP>
729.    To: <sip:masked@1.152.97.29:6517;transport=UDP;rinstance=9418840bbb26689f>;tag=81efd82f
730.    From: "pop" <sip:pop@faith.ski>;tag=9mKya0D7pNe5B
731.    Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764
732.    CSeq: 94866640 INVITE
733.    Content-Type: application/sdp
734.    User-Agent: Zoiper r55b5166
735.    Allow-Events: presence, kpml, talk
736.    Content-Length: 448
737.    
738.    v=0
739.    o=Zoiper 0 1 IN IP4 10.225.191.196
740.    s=Zoiper
741.    c=IN IP4 10.225.191.196
742.    t=0 0
743.    m=audio 38176 RTP/AVP 3 106 0 8 9 102 97 101
744.    a=rtpmap:3 GSM/8000
745.    a=rtpmap:106 opus/48000/2
746.    a=fmtp:106 minptime=20; cbr=1; maxaveragebitrate=40000; useinbandfec=1
747.    a=rtpmap:0 PCMU/8000
748.    a=rtpmap:8 PCMA/8000
749.    a=rtpmap:9 G722/8000
750.    a=rtpmap:102 G726-32/8000
751.    a=rtpmap:97 iLBC/8000
752.    a=fmtp:97 mode=30
753.    a=rtpmap:101 telephone-event/8000
754.    a=fmtp:101 0-16
755.    a=sendrecv
756.    ------------------------------------------------------------------------
757. 2016-08-05 23:56:52.778023 [DEBUG] sofia.c:6939 Channel sofia/internal/masked@1.152.97.29:6517 entering state [completing][200]
758. 2016-08-05 23:56:52.778023 [DEBUG] sofia.c:6949 Remote SDP:
759. v=0
760. o=Zoiper 0 1 IN IP4 10.225.191.196
761. s=Zoiper
762. c=IN IP4 10.225.191.196
763. t=0 0
764. m=audio 38176 RTP/AVP 3 106 0 8 9 102 97 101
765. a=rtpmap:3 GSM/8000
766. a=rtpmap:106 opus/48000/2
767. a=fmtp:106 minptime=20; cbr=1; maxaveragebitrate=40000; useinbandfec=1
768. a=rtpmap:0 PCMU/8000
769. a=rtpmap:8 PCMA/8000
770. a=rtpmap:9 G722/8000
771. a=rtpmap:102 G726-32/8000
772. a=rtpmap:97 iLBC/8000
773. a=fmtp:97 mode=30
774. a=rtpmap:101 telephone-event/8000
775. a=fmtp:101 0-16
776.  
777. send 410 bytes to udp/[1.152.97.29]:6517 at 23:56:52.785838:
778.    ------------------------------------------------------------------------
779.    ACK sip:masked@1.152.97.29:6517;transport=UDP SIP/2.0
780.    Via: SIP/2.0/UDP 45.32.188.45;rport;branch=z9hG4bKg8a82pDavQ0re
781.    Max-Forwards: 70
782.    From: "pop" <sip:pop@faith.ski>;tag=9mKya0D7pNe5B
783.    To: <sip:masked@1.152.97.29:6517;transport=UDP;rinstance=9418840bbb26689f>;tag=81efd82f
784.    Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764
785.    CSeq: 94866640 ACK
786.    Contact: <sip:mod_sofia@45.32.188.45:5060>
787.    Content-Length: 0
788.    
789.    ------------------------------------------------------------------------
790. 2016-08-05 23:56:52.778023 [DEBUG] sofia.c:6939 Channel sofia/internal/masked@1.152.97.29:6517 entering state [ready][200]
791. 2016-08-05 23:56:52.778023 [NOTICE] sofia.c:7932 Channel [sofia/internal/masked@1.152.97.29:6517] has been answered
792. 2016-08-05 23:56:52.778023 [DEBUG] switch_channel.c:3770 (sofia/internal/masked@1.152.97.29:6517) Callstate Change RINGING -> ACTIVE
793. 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/internal/masked@1.152.97.29:6517]
794. 2016-08-05 23:56:52.797454 [NOTICE] switch_ivr.c:779 Channel [sofia/internal/pop@faith.ski] has been answered
795. 2016-08-05 23:56:52.797454 [DEBUG] switch_channel.c:3770 (sofia/internal/pop@faith.ski) Callstate Change RINGING -> ACTIVE
796. 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/internal/masked@1.152.97.29:6517]
797. 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_bridge.c:1401 (sofia/internal/pop@faith.ski) State Change CS_EXECUTE -> CS_HIBERNATE
798. 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_bridge.c:1402 (sofia/internal/masked@1.152.97.29:6517) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
799. 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/pop@faith.ski) State EXECUTE going to sleep
800. 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/pop@faith.ski) Running State Change CS_HIBERNATE
801. 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/pop@faith.ski) State HIBERNATE
802. 2016-08-05 23:56:52.797454 [DEBUG] mod_sofia.c:179 sofia/internal/pop@faith.ski SOFIA HIBERNATE
803. send 1132 bytes to udp/[49.183.185.185]:23510 at 23:56:52.803585:
804.    ------------------------------------------------------------------------
805.    SIP/2.0 200 OK
806.    Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---0415a7d6262ece37;rport=23510
807.    From: <sip:pop@faith.ski;transport=UDP>;tag=6be5232a
808.    To: <sip:masked@faith.ski;transport=UDP>;tag=8Bt584v3Scrjg
809.    Call-ID: KUzX0zgTmklc6ZVhY5TgKw..
810.    CSeq: 2 INVITE
811.    Contact: <sip:masked@45.32.188.45:5060;transport=udp>
812.    User-Agent: FreeSWITCH
813.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
814.    Supported: timer, path, replaces
815.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
816.    Content-Type: application/sdp
817.    Content-Disposition: session
818.    Content-Length: 293
819.    Remote-Party-ID: "masked" <sip:masked@faith.ski>;party=calling;privacy=off;screen=no
820.    
821.    v=0
822.    o=Zoiper 8660380831970978990 1058209101210273600 IN IP4 10.225.191.196
823.    s=Zoiper
824.    c=IN IP4 10.225.191.196
825.    t=0 0
826.    m=audio 38176 RTP/AVP 3 0 8 9 101
827.    a=rtpmap:3 GSM/8000
828.    a=rtpmap:0 PCMU/8000
829.    a=rtpmap:8 PCMA/8000
830.    a=rtpmap:9 G722/8000
831.    a=rtpmap:101 telephone-event/8000
832.    a=fmtp:101 0-16
833.    ------------------------------------------------------------------------
834. 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/masked@1.152.97.29:6517) Running State Change CS_HIBERNATE
835. 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/masked@1.152.97.29:6517) State HIBERNATE
836. 2016-08-05 23:56:52.797454 [DEBUG] mod_sofia.c:179 sofia/internal/masked@1.152.97.29:6517 SOFIA HIBERNATE
837. 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:420 sofia/internal/masked@1.152.97.29:6517 Standard HIBERNATE
838. 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/masked@1.152.97.29:6517) State HIBERNATE going to sleep
839. 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_bridge.c:1211 sofia/internal/pop@faith.ski not hibernating due to active digit parser, semi-hibernation engaged.
840. 2016-08-05 23:56:52.797454 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [completed][200]
841. recv 429 bytes from udp/[49.183.185.185]:23510 at 23:56:53.065319:
842.    ------------------------------------------------------------------------
843.    ACK sip:masked@45.32.188.45:5060;transport=udp SIP/2.0
844.    Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---2d559a35d1dbd01d;rport
845.    Max-Forwards: 70
846.    Contact: <sip:pop@49.183.185.185:23510;transport=UDP>
847.    To: <sip:masked@faith.ski;transport=UDP>;tag=8Bt584v3Scrjg
848.    From: <sip:pop@faith.ski;transport=UDP>;tag=6be5232a
849.    Call-ID: KUzX0zgTmklc6ZVhY5TgKw..
850.    CSeq: 2 ACK
851.    User-Agent: Zoiper r55b5166
852.    Content-Length: 0
853.    
854.    ------------------------------------------------------------------------
855. 2016-08-05 23:56:53.058100 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [ready][200]
856. recv 740 bytes from udp/[1.152.97.2