1. [m[33m[44m.=======================================================.
2. |            _____ ____     ____ _     ___              |
3. |           |  ___/ ___|   / ___| |   |_ _|             |
4. |           | |_  \___ \  | |   | |    | |              |
5. |           |  _|  ___) | | |___| |___ | |              |
6. |           |_|   |____/   \____|_____|___|             |
7. |                                                       |
8. .=======================================================.
9. | Anthony Minessale II, Ken Rice,                       |
10. | Michael Jerris, Travis Cross                          |
11. | FreeSWITCH (http://www.freeswitch.org)                |
12. | Paypal Donations Appreciated: paypal@freeswitch.org   |
13. | Brought to you by ClueCon http://www.cluecon.com/     |
14. .=======================================================.
15.  
16. .===============================================================.
17. |       _                                                       |
18. |   ___| |_   _  ___  ___ ___  _ __         ___ ___  _ __ ___   |
19. |  / __| | | | |/ _ \/ __/ _ \| '_ \       / __/ _ \| '_ ` _ \  |
20. | | (__| | |_| |  __/ (_| (_) | | | |  _  | (_| (_) | | | | | | |
21. |  \___|_|\__,_|\___|\___\___/|_| |_| (_)  \___\___/|_| |_| |_| |
22. |                                                               |
23. .===============================================================.
24. [m
25. Type /help <enter> to see a list of commands
26.  
27.  
28.  
29. [m
30. [This app Best viewed at 160x60 or more..]
31. +OK log level 7 [7]
32. freeswitch@cpe003> Enabled sip debugging on internal
33. freeswitch@cpe003> UP 0 years, 0 days, 0 hours, 22 minutes, 21 seconds, 202 milliseconds, 122 microseconds
34. FreeSWITCH (Version 1.6.19 git b1b21d0 2017-11-20 16:34:16Z 64bit) is ready
35. 0 session(s) since startup
36. 0 session(s) - peak 0, last 5min 0
37. 0 session(s) per Sec out of max 30, peak 0, last 5min 0
38. 1000 session(s) max
39. min idle cpu 0.00/92.07
40. Current Stack Size/Max 240K/8192K
41.  
42. freeswitch@cpe003> recv 434 bytes from udp/[192.168.22.121]:5060 at 01:49:37.978723:
43.    ------------------------------------------------------------------------
44.    REGISTER sip:192.168.22.23 SIP/2.0
45.    Via: SIP/2.0/UDP 192.168.22.121;rport;branch=z9hG4bKzucalaxa
46.    Max-Forwards: 70
47.    To: "xq1000" <sip:1000@192.168.22.23>
48.    From: "xq1000" <sip:1000@192.168.22.23>;tag=zckjl
49.    Call-ID: jpbkvkxhsniejmo@mx1
50.    CSeq: 233 REGISTER
51.    Contact: <sip:1000@192.168.22.121>;expires=3600
52.    Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
53.    User-Agent: Twinkle/1.10.1
54.    Content-Length: 0
55.    
56.    ------------------------------------------------------------------------
57. send 616 bytes to udp/[192.168.22.121]:5060 at 01:49:37.982396:
58.    ------------------------------------------------------------------------
59.    SIP/2.0 401 Unauthorized
60.    Via: SIP/2.0/UDP 192.168.22.121;rport=5060;branch=z9hG4bKzucalaxa
61.    From: "xq1000" <sip:1000@192.168.22.23>;tag=zckjl
62.    To: "xq1000" <sip:1000@192.168.22.23>;tag=8vpmcyatrmDKF
63.    Call-ID: jpbkvkxhsniejmo@mx1
64.    CSeq: 233 REGISTER
65.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
66.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
67.    Supported: timer, path, replaces
68.    WWW-Authenticate: Digest realm="192.168.22.23", nonce="982ee8e5-79c8-46bd-9500-67078ef26245", algorithm=MD5, qop="auth"
69.    Content-Length: 0
70.    
71.    ------------------------------------------------------------------------
72. recv 663 bytes from udp/[192.168.22.121]:5060 at 01:49:46.408530:
73.    ------------------------------------------------------------------------
74.    REGISTER sip:192.168.22.23 SIP/2.0
75.    Via: SIP/2.0/UDP 192.168.22.121;rport;branch=z9hG4bKwlserdqf
76.    Max-Forwards: 70
77.    To: "xq1000" <sip:1000@192.168.22.23>
78.    From: "xq1000" <sip:1000@192.168.22.23>;tag=zckjl
79.    Call-ID: jpbkvkxhsniejmo@mx1
80.    CSeq: 234 REGISTER
81.    Contact: <sip:1000@192.168.22.121>;expires=3600
82.    Authorization: Digest username="1000",realm="192.168.22.23",nonce="982ee8e5-79c8-46bd-9500-67078ef26245",uri="sip:192.168.22.23",response="e0accc7d3ac03bac11420bb97dd0ddbe",algorithm=MD5,cnonce="831d47d7f1",qop=auth,nc=00000001
83.    Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
84.    User-Agent: Twinkle/1.10.1
85.    Content-Length: 0
86.    
87.    ------------------------------------------------------------------------
88. 2018-01-07 01:49:46.411017 [CONSOLE] mod_voicemail.c:4092 Event Thread Started
89. send 571 bytes to udp/[192.168.22.121]:5060 at 01:49:46.421129:
90.    ------------------------------------------------------------------------
91.    SIP/2.0 200 OK
92.    Via: SIP/2.0/UDP 192.168.22.121;rport=5060;branch=z9hG4bKwlserdqf
93.    From: "xq1000" <sip:1000@192.168.22.23>;tag=zckjl
94.    To: "xq1000" <sip:1000@192.168.22.23>;tag=95FDeSUXNX35a
95.    Call-ID: jpbkvkxhsniejmo@mx1
96.    CSeq: 234 REGISTER
97.    Contact: <sip:1000@192.168.22.121>;expires=3600
98.    Date: Sun, 07 Jan 2018 07:49:46 GMT
99.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
100.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
101.    Supported: timer, path, replaces
102.    Content-Length: 0
103.    
104.    ------------------------------------------------------------------------
105. send 952 bytes to udp/[192.168.22.121]:5060 at 01:49:46.424089:
106.    ------------------------------------------------------------------------
107.    NOTIFY sip:1000@192.168.22.121 SIP/2.0
108.    Via: SIP/2.0/UDP 192.168.22.23;rport;branch=z9hG4bK8QNyUp46F4gjH
109.    Max-Forwards: 70
110.    From: <sip:1000@192.168.22.23>;tag=aF95Fmc1j6Srp
111.    To: <sip:1000@192.168.22.23>
112.    Call-ID: 2bfde562-6e22-1236-de86-9c5c8e7b1324
113.    CSeq: 117319629 NOTIFY
114.    Contact: <sip:mod_sofia@192.168.22.23:5060>
115.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
116.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
117.    Supported: timer, path, replaces
118.    Event: message-summary
119.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
120.    Subscription-State: terminated;reason=noresource
121.    Content-Type: application/simple-message-summary
122.    Content-Length: 92
123.    
124.    Messages-Waiting: yes
125.    Message-Account: sip:1000@192.168.22.23
126.    Voice-Message: 2/0 (0/0)
127.    
128.    ------------------------------------------------------------------------
129. recv 316 bytes from udp/[192.168.22.121]:5060 at 01:49:46.431646:
130.    ------------------------------------------------------------------------
131.    SIP/2.0 200 OK
132.    Via: SIP/2.0/UDP 192.168.22.23;received=192.168.22.23;rport=5060;branch=z9hG4bK8QNyUp46F4gjH
133.    To: <sip:1000@192.168.22.23>;tag=ctrng
134.    From: <sip:1000@192.168.22.23>;tag=aF95Fmc1j6Srp
135.    Call-ID: 2bfde562-6e22-1236-de86-9c5c8e7b1324
136.    CSeq: 117319629 NOTIFY
137.    Server: Twinkle/1.10.1
138.    Content-Length: 0
139.    
140.    ------------------------------------------------------------------------
141. recv 798 bytes from udp/[192.168.22.121]:5060 at 01:49:54.061144:
142.    ------------------------------------------------------------------------
143.    INVITE sip:1100@192.168.22.23 SIP/2.0
144.    Via: SIP/2.0/UDP 192.168.22.121;rport;branch=z9hG4bKbqrfllts
145.    Max-Forwards: 70
146.    To: <sip:1100@192.168.22.23>
147.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
148.    Call-ID: ksvnqvxrdulmzyh@mx1
149.    CSeq: 389 INVITE
150.    Contact: <sip:1000@192.168.22.121>
151.    Content-Type: application/sdp
152.    Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
153.    Supported: replaces,norefersub,100rel
154.    User-Agent: Twinkle/1.10.1
155.    Content-Length: 313
156.    
157.    v=0
158.    o=twinkle 1632699621 1424409132 IN IP4 192.168.22.121
159.    s=-
160.    c=IN IP4 192.168.22.121
161.    t=0 0
162.    m=audio 8000 RTP/AVP 98 97 8 0 3 101
163.    a=rtpmap:98 speex/16000
164.    a=rtpmap:97 speex/8000
165.    a=rtpmap:8 PCMA/8000
166.    a=rtpmap:0 PCMU/8000
167.    a=rtpmap:3 GSM/8000
168.    a=rtpmap:101 telephone-event/8000
169.    a=fmtp:101 0-15
170.    a=ptime:20
171.    ------------------------------------------------------------------------
172. send 316 bytes to udp/[192.168.22.121]:5060 at 01:49:54.061820:
173.    ------------------------------------------------------------------------
174.    SIP/2.0 100 Trying
175.    Via: SIP/2.0/UDP 192.168.22.121;rport=5060;branch=z9hG4bKbqrfllts
176.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
177.    To: <sip:1100@192.168.22.23>
178.    Call-ID: ksvnqvxrdulmzyh@mx1
179.    CSeq: 389 INVITE
180.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
181.    Content-Length: 0
182.    
183.    ------------------------------------------------------------------------
184. 2018-01-07 01:49:54.051043 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@192.168.22.23 [ce6e9124-2d9d-4073-923f-9dfc3b87e384]
185. 2018-01-07 01:49:54.051043 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.22.23) Running State Change CS_NEW (Cur 1 Tot 1)
186. 2018-01-07 01:49:54.051043 [DEBUG] sofia.c:9873 sofia/internal/1000@192.168.22.23 receiving invite from 192.168.22.121:5060 version: 1.6.19 git b1b21d0 2017-11-20 16:34:16Z 64bit
187. 2018-01-07 01:49:54.051043 [DEBUG] sofia.c:10044 IP 192.168.22.121 Rejected by acl "domains". Falling back to Digest auth.
188. send 820 bytes to udp/[192.168.22.121]:5060 at 01:49:54.068030:
189.    ------------------------------------------------------------------------
190.    SIP/2.0 407 Proxy Authentication Required
191.    Via: SIP/2.0/UDP 192.168.22.121;rport=5060;branch=z9hG4bKbqrfllts
192.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
193.    To: <sip:1100@192.168.22.23>;tag=Br2yHFX4FFgBj
194.    Call-ID: ksvnqvxrdulmzyh@mx1
195.    CSeq: 389 INVITE
196.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
197.    Accept: application/sdp
198.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
199.    Supported: timer, path, replaces
200.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
201.    Proxy-Authenticate: Digest realm="192.168.22.23", nonce="1f4df9f2-50d0-430f-818f-4a7b741c74c4", algorithm=MD5, qop="auth"
202.    Content-Length: 0
203.    
204.    ------------------------------------------------------------------------
205. 2018-01-07 01:49:54.051043 [DEBUG] sofia.c:2334 detaching session ce6e9124-2d9d-4073-923f-9dfc3b87e384
206. 2018-01-07 01:49:54.051043 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@192.168.22.23) State NEW
207. recv 309 bytes from udp/[192.168.22.121]:5060 at 01:49:54.070040:
208.    ------------------------------------------------------------------------
209.    ACK sip:1100@192.168.22.23 SIP/2.0
210.    Via: SIP/2.0/UDP 192.168.22.121;rport;branch=z9hG4bKbqrfllts
211.    Max-Forwards: 70
212.    To: <sip:1100@192.168.22.23>;tag=Br2yHFX4FFgBj
213.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
214.    Call-ID: ksvnqvxrdulmzyh@mx1
215.    CSeq: 389 ACK
216.    User-Agent: Twinkle/1.10.1
217.    Content-Length: 0
218.    
219.    ------------------------------------------------------------------------
220. recv 1038 bytes from udp/[192.168.22.121]:5060 at 01:49:54.070861:
221.    ------------------------------------------------------------------------
222.    INVITE sip:1100@192.168.22.23 SIP/2.0
223.    Via: SIP/2.0/UDP 192.168.22.121;rport;branch=z9hG4bKykqkmqrs
224.    Max-Forwards: 70
225.    Proxy-Authorization: Digest username="1000",realm="192.168.22.23",nonce="1f4df9f2-50d0-430f-818f-4a7b741c74c4",uri="sip:1100@192.168.22.23",response="48a6f06ce2eca2d62889f12cf7795ed9",algorithm=MD5,cnonce="92449feb2b",qop=auth,nc=00000001
226.    To: <sip:1100@192.168.22.23>
227.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
228.    Call-ID: ksvnqvxrdulmzyh@mx1
229.    CSeq: 390 INVITE
230.    Contact: <sip:1000@192.168.22.121>
231.    Content-Type: application/sdp
232.    Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
233.    Supported: replaces,norefersub,100rel
234.    User-Agent: Twinkle/1.10.1
235.    Content-Length: 313
236.    
237.    v=0
238.    o=twinkle 1632699621 1424409132 IN IP4 192.168.22.121
239.    s=-
240.    c=IN IP4 192.168.22.121
241.    t=0 0
242.    m=audio 8000 RTP/AVP 98 97 8 0 3 101
243.    a=rtpmap:98 speex/16000
244.    a=rtpmap:97 speex/8000
245.    a=rtpmap:8 PCMA/8000
246.    a=rtpmap:0 PCMU/8000
247.    a=rtpmap:3 GSM/8000
248.    a=rtpmap:101 telephone-event/8000
249.    a=fmtp:101 0-15
250.    a=ptime:20
251.    ------------------------------------------------------------------------
252. send 316 bytes to udp/[192.168.22.121]:5060 at 01:49:54.071596:
253.    ------------------------------------------------------------------------
254.    SIP/2.0 100 Trying
255.    Via: SIP/2.0/UDP 192.168.22.121;rport=5060;branch=z9hG4bKykqkmqrs
256.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
257.    To: <sip:1100@192.168.22.23>
258.    Call-ID: ksvnqvxrdulmzyh@mx1
259.    CSeq: 390 INVITE
260.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
261.    Content-Length: 0
262.    
263.    ------------------------------------------------------------------------
264. 2018-01-07 01:49:54.071105 [DEBUG] sofia.c:2442 Re-attaching to session ce6e9124-2d9d-4073-923f-9dfc3b87e384
265. 2018-01-07 01:49:54.071105 [DEBUG] sofia.c:9873 sofia/internal/1000@192.168.22.23 receiving invite from 192.168.22.121:5060 version: 1.6.19 git b1b21d0 2017-11-20 16:34:16Z 64bit
266. 2018-01-07 01:49:54.071105 [DEBUG] sofia.c:10044 IP 192.168.22.121 Rejected by acl "domains". Falling back to Digest auth.
267. 2018-01-07 01:49:54.091138 [DEBUG] sofia.c:7084 Channel sofia/internal/1000@192.168.22.23 entering state [received][100]
268. 2018-01-07 01:49:54.091138 [DEBUG] sofia.c:7094 Remote SDP:
269. v=0
270. o=twinkle 1632699621 1424409132 IN IP4 192.168.22.121
271. s=-
272. c=IN IP4 192.168.22.121
273. t=0 0
274. m=audio 8000 RTP/AVP 98 97 8 0 3 101
275. a=rtpmap:98 speex/16000
276. a=rtpmap:97 speex/8000
277. a=rtpmap:8 PCMA/8000
278. a=rtpmap:0 PCMU/8000
279. a=rtpmap:3 GSM/8000
280. a=rtpmap:101 telephone-event/8000
281. a=fmtp:101 0-15
282. a=ptime:20
283.  
284. 2018-01-07 01:49:54.091138 [DEBUG] sofia.c:7486 (sofia/internal/1000@192.168.22.23) State Change CS_NEW -> CS_INIT
285. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.22.23) Running State Change CS_INIT (Cur 1 Tot 1)
286. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@192.168.22.23) State INIT
287. 2018-01-07 01:49:54.091138 [DEBUG] mod_sofia.c:90 sofia/internal/1000@192.168.22.23 SOFIA INIT
288. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@192.168.22.23 Standard INIT
289. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@192.168.22.23) State Change CS_INIT -> CS_ROUTING
290. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@192.168.22.23) State INIT going to sleep
291. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.22.23) Running State Change CS_ROUTING (Cur 1 Tot 1)
292. 2018-01-07 01:49:54.091138 [DEBUG] switch_channel.c:2249 (sofia/internal/1000@192.168.22.23) Callstate Change DOWN -> RINGING
293. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@192.168.22.23) State ROUTING
294. 2018-01-07 01:49:54.091138 [DEBUG] mod_sofia.c:143 sofia/internal/1000@192.168.22.23 SOFIA ROUTING
295. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1000@192.168.22.23 Standard ROUTING
296. 2018-01-07 01:49:54.091138 [INFO] mod_dialplan_xml.c:637 Processing xq1000 <1000>->1100 in context default
297. Dialplan: sofia/internal/1000@192.168.22.23 parsing [default->Local_FXS_Extension] continue=false
298. Dialplan: sofia/internal/1000@192.168.22.23 Regex (PASS) [Local_FXS_Extension] destination_number(1100) =~ /^(1100)$/ break=on-false
299. Dialplan: sofia/internal/1000@192.168.22.23 Action set(dialed_extension=1100)
300. Dialplan: sofia/internal/1000@192.168.22.23 Action export(dialed_extension=1100)
301. Dialplan: sofia/internal/1000@192.168.22.23 Action bind_meta_app(1 b s execute_extension::dx XML features)
302. Dialplan: sofia/internal/1000@192.168.22.23 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
303. Dialplan: sofia/internal/1000@192.168.22.23 Action bind_meta_app(3 b s execute_extension::cf XML features)
304. Dialplan: sofia/internal/1000@192.168.22.23 Action set(ringback=${us-ring})
305. Dialplan: sofia/internal/1000@192.168.22.23 Action set(transfer_ringback=local_stream://moh)
306. Dialplan: sofia/internal/1000@192.168.22.23 Action set(call_timeout=10)
307. Dialplan: sofia/internal/1000@192.168.22.23 Action set(hangup_after_bridge=true)
308. Dialplan: sofia/internal/1000@192.168.22.23 Action set(continue_on_fail=true)
309. Dialplan: sofia/internal/1000@192.168.22.23 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
310. Dialplan: sofia/internal/1000@192.168.22.23 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
311. Dialplan: sofia/internal/1000@192.168.22.23 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
312. Dialplan: sofia/internal/1000@192.168.22.23 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
313. Dialplan: sofia/internal/1000@192.168.22.23 Action bridge(freetdm/1/1)
314. Dialplan: sofia/internal/1000@192.168.22.23 Action answer()
315. Dialplan: sofia/internal/1000@192.168.22.23 Action sleep(1000)
316. Dialplan: sofia/internal/1000@192.168.22.23 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
317. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1000@192.168.22.23) State Change CS_ROUTING -> CS_EXECUTE
318. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@192.168.22.23) State ROUTING going to sleep
319. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.22.23) Running State Change CS_EXECUTE (Cur 1 Tot 1)
320. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1000@192.168.22.23) State EXECUTE
321. 2018-01-07 01:49:54.091138 [DEBUG] mod_sofia.c:198 sofia/internal/1000@192.168.22.23 SOFIA EXECUTE
322. 2018-01-07 01:49:54.091138 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1000@192.168.22.23 Standard EXECUTE
323. EXECUTE sofia/internal/1000@192.168.22.23 set(dialed_extension=1100)
324. 2018-01-07 01:49:54.091138 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1000@192.168.22.23 [dialed_extension]=[1100]
325. EXECUTE sofia/internal/1000@192.168.22.23 export(dialed_extension=1100)
326. 2018-01-07 01:49:54.091138 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1100]
327. EXECUTE sofia/internal/1000@192.168.22.23 bind_meta_app(1 b s execute_extension::dx XML features)
328. 2018-01-07 01:49:54.091138 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *1 execute_extension::dx XML features
329. EXECUTE sofia/internal/1000@192.168.22.23 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1000.2018-01-07-01-49-54.wav)
330. 2018-01-07 01:49:54.091138 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1000.2018-01-07-01-49-54.wav
331. EXECUTE sofia/internal/1000@192.168.22.23 bind_meta_app(3 b s execute_extension::cf XML features)
332. 2018-01-07 01:49:54.091138 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *3 execute_extension::cf XML features
333. EXECUTE sofia/internal/1000@192.168.22.23 set(ringback=%(2000,4000,440,480))
334. 2018-01-07 01:49:54.091138 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1000@192.168.22.23 [ringback]=[%(2000,4000,440,480)]
335. EXECUTE sofia/internal/1000@192.168.22.23 set(transfer_ringback=local_stream://moh)
336. 2018-01-07 01:49:54.091138 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1000@192.168.22.23 [transfer_ringback]=[local_stream://moh]
337. EXECUTE sofia/internal/1000@192.168.22.23 set(call_timeout=10)
338. 2018-01-07 01:49:54.091138 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1000@192.168.22.23 [call_timeout]=[10]
339. EXECUTE sofia/internal/1000@192.168.22.23 set(hangup_after_bridge=true)
340. 2018-01-07 01:49:54.091138 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1000@192.168.22.23 [hangup_after_bridge]=[true]
341. EXECUTE sofia/internal/1000@192.168.22.23 set(continue_on_fail=true)
342. 2018-01-07 01:49:54.091138 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1000@192.168.22.23 [continue_on_fail]=[true]
343. EXECUTE sofia/internal/1000@192.168.22.23 hash(insert/192.168.22.23-call_return/1100/1000)
344. EXECUTE sofia/internal/1000@192.168.22.23 hash(insert/192.168.22.23-last_dial_ext/1100/ce6e9124-2d9d-4073-923f-9dfc3b87e384)
345. EXECUTE sofia/internal/1000@192.168.22.23 set(called_party_callgroup=)
346. 2018-01-07 01:49:54.131048 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1000@192.168.22.23 [called_party_callgroup]=[UNDEF]
347. EXECUTE sofia/internal/1000@192.168.22.23 hash(insert/192.168.22.23-last_dial//ce6e9124-2d9d-4073-923f-9dfc3b87e384)
348. EXECUTE sofia/internal/1000@192.168.22.23 bridge(freetdm/1/1)
349. 2018-01-07 01:49:54.131048 [DEBUG] switch_channel.c:1250 sofia/internal/1000@192.168.22.23 EXPORTING[export_vars] [dialed_extension]=[1100] to event
350. 2018-01-07 01:49:54.131048 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
351. 2018-01-07 01:49:54.131048 [DEBUG] mod_freetdm.c:401 Set codec PCMU 20ms
352. 2018-01-07 01:49:54.131048 [DEBUG] mod_freetdm.c:1249 Connect outbound channel FreeTDM/1:1/
353. 2018-01-07 01:49:54.131048 [NOTICE] switch_channel.c:1104 New Channel FreeTDM/1:1/ [2a61299d-0afa-4208-a93d-7613992c3e18]
354. 2018-01-07 01:49:54.131048 [DEBUG] mod_freetdm.c:1258 (FreeTDM/1:1/) State Change CS_NEW -> CS_INIT
355. 2018-01-07 01:49:54.131048 [DEBUG] mod_freetdm.c:1277 Attached session 2a61299d-0afa-4208-a93d-7613992c3e18 to channel 1:1
356. 2018-01-07 01:49:54.131048 [DEBUG] ftmod_analog.c:83 [s1c1][1:1] Changed state from DOWN to GENRING
357. 2018-01-07 01:49:54.131048 [DEBUG] ftmod_analog.c:437 [s1c1][1:1] ANALOG CHANNEL thread starting.
358. 2018-01-07 01:49:54.131048 [DEBUG] ftdm_io.c:3406 [s1c1][1:1] Enabled software DTMF detector
359. 2018-01-07 01:49:54.131048 [DEBUG] ftmod_analog.c:457 [s1c1][1:1] Initialized DTMF detection
360. 2018-01-07 01:49:54.131048 [DEBUG] ftmod_analog.c:638 [s1c1][1:1] Completed state change from DOWN to GENRING in 2 ms
361. 2018-01-07 01:49:54.131048 [DEBUG] ftmod_analog.c:644 [s1c1][1:1] Executing state handler on 1:1 for GENRING
362. 2018-01-07 01:49:54.131048 [DEBUG] mod_freetdm.c:2370 got FXS sig [PROGRESS]
363. 2018-01-07 01:49:54.131048 [NOTICE] mod_freetdm.c:2387 Ring-Ready FreeTDM/1:1/!
364. 2018-01-07 01:49:54.131048 [DEBUG] switch_channel.c:3346 (FreeTDM/1:1/) Callstate Change DOWN -> RINGING
365. 2018-01-07 01:49:54.151046 [DEBUG] ftmod_wanpipe.c:1005 [s1c1][1:1] First packet read stats: Rx queue len: 0, Rx queue size: 10
366. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:584 (FreeTDM/1:1/) Running State Change CS_INIT (Cur 2 Tot 2)
367. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:627 (FreeTDM/1:1/) State INIT
368. 2018-01-07 01:49:54.631045 [DEBUG] mod_freetdm.c:428 (FreeTDM/1:1/) State Change CS_INIT -> CS_ROUTING
369. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:627 (FreeTDM/1:1/) State INIT going to sleep
370. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:584 (FreeTDM/1:1/) Running State Change CS_ROUTING (Cur 2 Tot 2)
371. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:643 (FreeTDM/1:1/) State ROUTING
372. 2018-01-07 01:49:54.631045 [DEBUG] mod_freetdm.c:451 FreeTDM/1:1/ CHANNEL ROUTING
373. 2018-01-07 01:49:54.631045 [DEBUG] switch_ivr_originate.c:67 (FreeTDM/1:1/) State Change CS_ROUTING -> CS_CONSUME_MEDIA
374. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:643 (FreeTDM/1:1/) State ROUTING going to sleep
375. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:584 (FreeTDM/1:1/) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 2)
376. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:662 (FreeTDM/1:1/) State CONSUME_MEDIA
377. 2018-01-07 01:49:54.631045 [DEBUG] switch_core_state_machine.c:662 (FreeTDM/1:1/) State CONSUME_MEDIA going to sleep
378. 2018-01-07 01:49:54.631045 [INFO] switch_ivr_originate.c:1215 Sending early media
379. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[opus:116:48000:20:0:1]
380. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[G722:9:8000:20:64000:1]
381. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
382. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
383. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[opus:116:48000:20:0:1]
384. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[G722:9:8000:20:64000:1]
385. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
386. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
387. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
388. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
389. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
390. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
391. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
392. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
393. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
394. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
395. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
396. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
397. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
398. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
399. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
400. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
401. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
402. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/1000@192.168.22.23 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
403. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@192.168.22.23 Original read codec set to PCMA:8
404. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
405. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:4767 sofia/internal/1000@192.168.22.23 Set 2833 dtmf send payload to 101 recv payload to 101
406. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/1000@192.168.22.23] 192.168.22.23 port 27144 -> 192.168.22.121 port 8000 codec: 8 ms: 20
407. 2018-01-07 01:49:54.651054 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
408. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:7180 sofia/internal/1000@192.168.22.23 Set 2833 dtmf send payload to 101
409. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:7187 sofia/internal/1000@192.168.22.23 Set 2833 dtmf receive payload to 101
410. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:7210 sofia/internal/1000@192.168.22.23 Set rtp dtmf delay to 40
411. 2018-01-07 01:49:54.651054 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@192.168.22.23!
412. 2018-01-07 01:49:54.651054 [DEBUG] switch_channel.c:3474 (sofia/internal/1000@192.168.22.23) Callstate Change RINGING -> EARLY
413. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/1000@192.168.22.23.
414. 2018-01-07 01:49:54.651054 [DEBUG] mod_sofia.c:2364 Ring SDP:
415. v=0
416. o=FreeSWITCH 1515284250 1515284251 IN IP4 192.168.22.23
417. s=FreeSWITCH
418. c=IN IP4 192.168.22.23
419. t=0 0
420. m=audio 27144 RTP/AVP 8 101
421. a=rtpmap:8 PCMA/8000
422. a=rtpmap:101 telephone-event/8000
423. a=fmtp:101 0-16
424. a=ptime:20
425. a=sendrecv
426.  
427. 2018-01-07 01:49:54.651054 [DEBUG] switch_ivr_originate.c:1273 Raw Codec Activation Success L16@8000hz 1 channel 20ms
428. 2018-01-07 01:49:54.651054 [DEBUG] switch_core_codec.c:223 sofia/internal/1000@192.168.22.23 Push codec L16:100
429. send 1109 bytes to udp/[192.168.22.121]:5060 at 01:49:54.669763:
430.    ------------------------------------------------------------------------
431.    SIP/2.0 183 Session Progress
432.    Via: SIP/2.0/UDP 192.168.22.121;rport=5060;branch=z9hG4bKykqkmqrs
433.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
434.    To: <sip:1100@192.168.22.23>;tag=c1UQKae8cr6XD
435.    Call-ID: ksvnqvxrdulmzyh@mx1
436.    CSeq: 390 INVITE
437.    Contact: <sip:1100@192.168.22.23:5060;transport=udp>
438.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
439.    Accept: application/sdp
440.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
441.    Supported: timer, path, replaces
442.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
443.    Content-Type: application/sdp
444.    Content-Disposition: session
445.    Content-Length: 222
446.    Remote-Party-ID: "1100" <sip:1100@192.168.22.23>;party=calling;privacy=off;screen=no
447.    
448.    v=0
449.    o=FreeSWITCH 1515284250 1515284251 IN IP4 192.168.22.23
450.    s=FreeSWITCH
451.    c=IN IP4 192.168.22.23
452.    t=0 0
453.    m=audio 27144 RTP/AVP 8 101
454.    a=rtpmap:8 PCMA/8000
455.    a=rtpmap:101 telephone-event/8000
456.    a=fmtp:101 0-16
457.    a=ptime:20
458.    ------------------------------------------------------------------------
459. 2018-01-07 01:49:54.651054 [DEBUG] switch_ivr_originate.c:1342 Play Ringback Tone [%(2000,4000,440,480)]
460. 2018-01-07 01:49:54.691083 [DEBUG] sofia.c:7084 Channel sofia/internal/1000@192.168.22.23 entering state [early][183]
461. 2018-01-07 01:49:54.731049 [DEBUG] ftmod_wanpipe.c:1678 [s1c1][1:1] read wanpipe event 5
462. 2018-01-07 01:49:54.731049 [DEBUG] ftmod_wanpipe.c:1462 [s1c1][1:1] Got wanpipe OFFHOOK
463. 2018-01-07 01:49:54.731049 [DEBUG] ftmod_wanpipe.c:1685 [s1c1][1:1] Ignoring event for now
464. 2018-01-07 01:49:54.811034 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
465. 2018-01-07 01:49:54.891028 [DEBUG] ftmod_wanpipe.c:1642 [s1c1][1:1] Diff since last event = 153 ms, delivering OFFHOOK now
466. 2018-01-07 01:49:54.891028 [DEBUG] ftmod_analog.c:1002 [s1c1][1:1] Received event [OFFHOOK] in state [GENRING]
467. 2018-01-07 01:49:54.891028 [DEBUG] ftmod_analog.c:1090 [s1c1][1:1] Changed state from GENRING to UP
468. 2018-01-07 01:49:54.891028 [DEBUG] ftmod_analog.c:638 [s1c1][1:1] Completed state change from GENRING to UP in 4 ms
469. 2018-01-07 01:49:54.891028 [DEBUG] ftmod_analog.c:644 [s1c1][1:1] Executing state handler on 1:1 for UP
470. 2018-01-07 01:49:54.891028 [DEBUG] ftmod_analog.c:657 [s1c1][1:1] Cancel FSK transmit due to early answer.
471. 2018-01-07 01:49:54.891028 [DEBUG] mod_freetdm.c:2370 got FXS sig [UP]
472. 2018-01-07 01:49:54.891028 [NOTICE] mod_freetdm.c:2377 Channel [FreeTDM/1:1/] has been answered
473. 2018-01-07 01:49:54.891028 [DEBUG] switch_channel.c:3773 (FreeTDM/1:1/) Callstate Change RINGING -> ACTIVE
474. 2018-01-07 01:49:54.891028 [DEBUG] ftdm_io.c:3406 [s1c1][1:1] Enabled software DTMF detector
475. 2018-01-07 01:49:54.911028 [DEBUG] switch_core_codec.c:248 sofia/internal/1000@192.168.22.23 Restore previous codec PCMA:8.
476. 2018-01-07 01:49:54.911028 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/1000@192.168.22.23.
477. 2018-01-07 01:49:54.911028 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/1000@192.168.22.23:
478. v=0
479. o=FreeSWITCH 1515284250 1515284252 IN IP4 192.168.22.23
480. s=FreeSWITCH
481. c=IN IP4 192.168.22.23
482. t=0 0
483. m=audio 27144 RTP/AVP 8 101
484. a=rtpmap:8 PCMA/8000
485. a=rtpmap:101 telephone-event/8000
486. a=fmtp:101 0-16
487. a=ptime:20
488. a=sendrecv
489.  
490. send 1076 bytes to udp/[192.168.22.121]:5060 at 01:49:54.918870:
491.    ------------------------------------------------------------------------
492.    SIP/2.0 200 OK
493.    Via: SIP/2.0/UDP 192.168.22.121;rport=5060;branch=z9hG4bKykqkmqrs
494.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
495.    To: <sip:1100@192.168.22.23>;tag=c1UQKae8cr6XD
496.    Call-ID: ksvnqvxrdulmzyh@mx1
497.    CSeq: 390 INVITE
498.    Contact: <sip:1100@192.168.22.23:5060;transport=udp>
499.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
500.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
501.    Supported: timer, path, replaces
502.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
503.    Content-Type: application/sdp
504.    Content-Disposition: session
505.    Content-Length: 222
506.    Remote-Party-ID: "Outbound Call" <sip:1@192.168.22.23>;party=calling;privacy=off;screen=no
507.    
508.    v=0
509.    o=FreeSWITCH 1515284250 1515284251 IN IP4 192.168.22.23
510.    s=FreeSWITCH
511.    c=IN IP4 192.168.22.23
512.    t=0 0
513.    m=audio 27144 RTP/AVP 8 101
514.    a=rtpmap:8 PCMA/8000
515.    a=rtpmap:101 telephone-event/8000
516.    a=fmtp:101 0-16
517.    a=ptime:20
518.    ------------------------------------------------------------------------
519. 2018-01-07 01:49:54.911028 [NOTICE] switch_ivr_originate.c:3647 Channel [sofia/internal/1000@192.168.22.23] has been answered
520. 2018-01-07 01:49:54.911028 [DEBUG] switch_channel.c:3773 (sofia/internal/1000@192.168.22.23) Callstate Change EARLY -> ACTIVE
521. 2018-01-07 01:49:54.911028 [DEBUG] sofia.c:7084 Channel sofia/internal/1000@192.168.22.23 entering state [completed][200]
522. 2018-01-07 01:49:54.911028 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [FreeTDM/1:1/]
523. 2018-01-07 01:49:54.911028 [DEBUG] switch_ivr_bridge.c:1614 (FreeTDM/1:1/) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
524. 2018-01-07 01:49:54.911028 [DEBUG] switch_core_state_machine.c:584 (FreeTDM/1:1/) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 2)
525. 2018-01-07 01:49:54.911028 [DEBUG] switch_core_state_machine.c:653 (FreeTDM/1:1/) State EXCHANGE_MEDIA
526. 2018-01-07 01:49:54.911028 [DEBUG] mod_freetdm.c:673 CHANNEL EXCHANGE_MEDIA
527. recv 568 bytes from udp/[192.168.22.121]:5060 at 01:49:54.925733:
528.    ------------------------------------------------------------------------
529.    ACK sip:1100@192.168.22.23:5060;transport=udp SIP/2.0
530.    Via: SIP/2.0/UDP 192.168.22.121;rport;branch=z9hG4bKrmxueras
531.    Max-Forwards: 70
532.    Proxy-Authorization: Digest username="1000",realm="192.168.22.23",nonce="1f4df9f2-50d0-430f-818f-4a7b741c74c4",uri="sip:1100@192.168.22.23",response="48a6f06ce2eca2d62889f12cf7795ed9",algorithm=MD5,cnonce="92449feb2b",qop=auth,nc=00000001
533.    To: <sip:1100@192.168.22.23>;tag=c1UQKae8cr6XD
534.    From: "xq1000" <sip:1000@192.168.22.23>;tag=ewsya
535.    Call-ID: ksvnqvxrdulmzyh@mx1
536.    CSeq: 390 ACK
537.    User-Agent: Twinkle/1.10.1
538.    Content-Length: 0
539.    
540.    ------------------------------------------------------------------------
541. 2018-01-07 01:49:54.931034 [DEBUG] sofia.c:7084 Channel sofia/internal/1000@192.168.22.23 entering state [ready][200]
542. 2018-01-07 01:49:54.971023 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
543. 2018-01-07 01:49:54.971023 [DEBUG] ftmod_wanpipe.c:941 [s1c1][1:1] First packet write stats: Tx queue len: 0, Tx queue size: 0, Tx idle: 0
544. recv 435 bytes from udp/[192.168.22.122]:5060 at 01:51:10.483096:
545.    ------------------------------------------------------------------------
546.    REGISTER sip:192.168.22.23 SIP/2.0
547.    Via: SIP/2.0/UDP 192.168.22.122;rport;branch=z9hG4bKrnnyzlxo
548.    Max-Forwards: 70
549.    To: "xq1001" <sip:1001@192.168.22.23>
550.    From: "xq1001" <sip:1001@192.168.22.23>;tag=mdmjv
551.    Call-ID: zzywitobkwwnxdp@mx16
552.    CSeq: 949 REGISTER
553.    Contact: <sip:1001@192.168.22.122>;expires=3600
554.    Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
555.    User-Agent: Twinkle/1.10.1
556.    Content-Length: 0
557.    
558.    ------------------------------------------------------------------------
559. send 617 bytes to udp/[192.168.22.122]:5060 at 01:51:10.486602:
560.    ------------------------------------------------------------------------
561.    SIP/2.0 401 Unauthorized
562.    Via: SIP/2.0/UDP 192.168.22.122;rport=5060;branch=z9hG4bKrnnyzlxo
563.    From: "xq1001" <sip:1001@192.168.22.23>;tag=mdmjv
564.    To: "xq1001" <sip:1001@192.168.22.23>;tag=DaNgN5yBa1vgS
565.    Call-ID: zzywitobkwwnxdp@mx16
566.    CSeq: 949 REGISTER
567.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
568.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
569.    Supported: timer, path, replaces
570.    WWW-Authenticate: Digest realm="192.168.22.23", nonce="84b44a4b-60c3-454a-ab09-ecc3aa85e0e7", algorithm=MD5, qop="auth"
571.    Content-Length: 0
572.    
573.    ------------------------------------------------------------------------
574. recv 664 bytes from udp/[192.168.22.122]:5060 at 01:51:28.844920:
575.    ------------------------------------------------------------------------
576.    REGISTER sip:192.168.22.23 SIP/2.0
577.    Via: SIP/2.0/UDP 192.168.22.122;rport;branch=z9hG4bKzxwxmvdb
578.    Max-Forwards: 70
579.    To: "xq1001" <sip:1001@192.168.22.23>
580.    From: "xq1001" <sip:1001@192.168.22.23>;tag=mdmjv
581.    Call-ID: zzywitobkwwnxdp@mx16
582.    CSeq: 950 REGISTER
583.    Contact: <sip:1001@192.168.22.122>;expires=3600
584.    Authorization: Digest username="1001",realm="192.168.22.23",nonce="84b44a4b-60c3-454a-ab09-ecc3aa85e0e7",uri="sip:192.168.22.23",response="1a63f6e4faa3492dea40e12baa5d54f1",algorithm=MD5,cnonce="58b293c21c",qop=auth,nc=00000001
585.    Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
586.    User-Agent: Twinkle/1.10.1
587.    Content-Length: 0
588.    
589.    ------------------------------------------------------------------------
590. send 572 bytes to udp/[192.168.22.122]:5060 at 01:51:28.858644:
591.    ------------------------------------------------------------------------
592.    SIP/2.0 200 OK
593.    Via: SIP/2.0/UDP 192.168.22.122;rport=5060;branch=z9hG4bKzxwxmvdb
594.    From: "xq1001" <sip:1001@192.168.22.23>;tag=mdmjv
595.    To: "xq1001" <sip:1001@192.168.22.23>;tag=eKe9p0FF79j3m
596.    Call-ID: zzywitobkwwnxdp@mx16
597.    CSeq: 950 REGISTER
598.    Contact: <sip:1001@192.168.22.122>;expires=3600
599.    Date: Sun, 07 Jan 2018 07:51:28 GMT
600.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
601.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
602.    Supported: timer, path, replaces
603.    Content-Length: 0
604.    
605.    ------------------------------------------------------------------------
606. recv 571 bytes from udp/[192.168.22.122]:5060 at 01:51:28.860952:
607.    ------------------------------------------------------------------------
608.    PUBLISH sip:1001@192.168.22.23 SIP/2.0
609.    Via: SIP/2.0/UDP 192.168.22.122;rport;branch=z9hG4bKhgrfhefv
610.    Max-Forwards: 70
611.    To: "xq1001" <sip:1001@192.168.22.23>
612.    From: "xq1001" <sip:1001@192.168.22.23>;tag=hgpte
613.    Call-ID: tvqhmktmxunwsli@mx16
614.    CSeq: 411 PUBLISH
615.    Content-Type: application/pidf+xml
616.    Event: presence
617.    Expires: 3600
618.    User-Agent: Twinkle/1.10.1
619.    Content-Length: 192
620.    
621.    <?xml version="1.0" encoding="UTF-8"?>
622.    <presence xmlns="urn:ietf:params:xml:ns:pidf" entity="sip:1001@192.168.22.23"><tuple id="jwzpzo"><status><basic>open</basic></status></tuple></presence>
623.    ------------------------------------------------------------------------
624. send 721 bytes to udp/[192.168.22.122]:5060 at 01:51:28.867655:
625.    ------------------------------------------------------------------------
626.    SIP/2.0 200 OK
627.    Via: SIP/2.0/UDP 192.168.22.122;rport=5060;branch=z9hG4bKhgrfhefv
628.    From: "xq1001" <sip:1001@192.168.22.23>;tag=hgpte
629.    To: "xq1001" <sip:1001@192.168.22.23>;tag=Fv71rU0j4j9Ng
630.    Call-ID: tvqhmktmxunwsli@mx16
631.    CSeq: 411 PUBLISH
632.    Contact: <sip:192.168.22.23>
633.    Expires: 3600
634.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
635.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
636.    Supported: timer, path, replaces
637.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
638.    SIP-ETag: E4BJ6259
639.    Content-Length: 0
640.    
641.    ------------------------------------------------------------------------
642. send 952 bytes to udp/[192.168.22.122]:5060 at 01:51:28.909429:
643.    ------------------------------------------------------------------------
644.    NOTIFY sip:1001@192.168.22.122 SIP/2.0
645.    Via: SIP/2.0/UDP 192.168.22.23;rport;branch=z9hG4bK90eQXHNaDD74c
646.    Max-Forwards: 70
647.    From: <sip:1001@192.168.22.23>;tag=g50ttpHp1UZ8B
648.    To: <sip:1001@192.168.22.23>
649.    Call-ID: 6913f6dc-6e22-1236-de86-9c5c8e7b1324
650.    CSeq: 117319680 NOTIFY
651.    Contact: <sip:mod_sofia@192.168.22.23:5060>
652.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
653.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
654.    Supported: timer, path, replaces
655.    Event: message-summary
656.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
657.    Subscription-State: terminated;reason=noresource
658.    Content-Type: application/simple-message-summary
659.    Content-Length: 92
660.    
661.    Messages-Waiting: yes
662.    Message-Account: sip:1001@192.168.22.23
663.    Voice-Message: 1/0 (0/0)
664.    
665.    ------------------------------------------------------------------------
666. recv 316 bytes from udp/[192.168.22.122]:5060 at 01:51:28.914401:
667.    ------------------------------------------------------------------------
668.    SIP/2.0 200 OK
669.    Via: SIP/2.0/UDP 192.168.22.23;received=192.168.22.23;rport=5060;branch=z9hG4bK90eQXHNaDD74c
670.    To: <sip:1001@192.168.22.23>;tag=ojxwy
671.    From: <sip:1001@192.168.22.23>;tag=g50ttpHp1UZ8B
672.    Call-ID: 6913f6dc-6e22-1236-de86-9c5c8e7b1324
673.    CSeq: 117319680 NOTIFY
674.    Server: Twinkle/1.10.1
675.    Content-Length: 0
676.    
677.    ------------------------------------------------------------------------
678. recv 798 bytes from udp/[192.168.22.122]:5060 at 01:51:43.142660:
679.    ------------------------------------------------------------------------
680.    INVITE sip:9664@192.168.22.23 SIP/2.0
681.    Via: SIP/2.0/UDP 192.168.22.122;rport;branch=z9hG4bKsjxiuufv
682.    Max-Forwards: 70
683.    To: <sip:9664@192.168.22.23>
684.    From: "xq1001" <sip:1001@192.168.22.23>;tag=sdofb
685.    Call-ID: hxtpeywcrtubfgu@mx16
686.    CSeq: 720 INVITE
687.    Contact: <sip:1001@192.168.22.122>
688.    Content-Type: application/sdp
689.    Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
690.    Supported: replaces,norefersub,100rel
691.    User-Agent: Twinkle/1.10.1
692.    Content-Length: 312
693.    
694.    v=0
695.    o=twinkle 1321715876 379379822 IN IP4 192.168.22.122
696.    s=-
697.    c=IN IP4 192.168.22.122
698.    t=0 0
699.    m=audio 8000 RTP/AVP 98 97 8 0 3 101
700.    a=rtpmap:98 speex/16000
701.    a=rtpmap:97 speex/8000
702.    a=rtpmap:8 PCMA/8000
703.    a=rtpmap:0 PCMU/8000
704.    a=rtpmap:3 GSM/8000
705.    a=rtpmap:101 telephone-event/8000
706.    a=fmtp:101 0-15
707.    a=ptime:20
708.    ------------------------------------------------------------------------
709. send 317 bytes to udp/[192.168.22.122]:5060 at 01:51:43.143897:
710.    ------------------------------------------------------------------------
711.    SIP/2.0 100 Trying
712.    Via: SIP/2.0/UDP 192.168.22.122;rport=5060;branch=z9hG4bKsjxiuufv
713.    From: "xq1001" <sip:1001@192.168.22.23>;tag=sdofb
714.    To: <sip:9664@192.168.22.23>
715.    Call-ID: hxtpeywcrtubfgu@mx16
716.    CSeq: 720 INVITE
717.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
718.    Content-Length: 0
719.    
720.    ------------------------------------------------------------------------
721. 2018-01-07 01:51:43.111399 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@192.168.22.23 [412c1118-efb2-4f76-b912-fa6455b7dbf9]
722. 2018-01-07 01:51:43.111399 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.22.23) Running State Change CS_NEW (Cur 3 Tot 3)
723. 2018-01-07 01:51:43.111399 [DEBUG] sofia.c:9873 sofia/internal/1001@192.168.22.23 receiving invite from 192.168.22.122:5060 version: 1.6.19 git b1b21d0 2017-11-20 16:34:16Z 64bit
724. 2018-01-07 01:51:43.111399 [DEBUG] sofia.c:10044 IP 192.168.22.122 Rejected by acl "domains". Falling back to Digest auth.
725. send 821 bytes to udp/[192.168.22.122]:5060 at 01:51:43.149078:
726.    ------------------------------------------------------------------------
727.    SIP/2.0 407 Proxy Authentication Required
728.    Via: SIP/2.0/UDP 192.168.22.122;rport=5060;branch=z9hG4bKsjxiuufv
729.    From: "xq1001" <sip:1001@192.168.22.23>;tag=sdofb
730.    To: <sip:9664@192.168.22.23>;tag=HetKvH2Sy4NUQ
731.    Call-ID: hxtpeywcrtubfgu@mx16
732.    CSeq: 720 INVITE
733.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
734.    Accept: application/sdp
735.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
736.    Supported: timer, path, replaces
737.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
738.    Proxy-Authenticate: Digest realm="192.168.22.23", nonce="e292d3a8-95c8-4233-8f32-042467938893", algorithm=MD5, qop="auth"
739.    Content-Length: 0
740.    
741.    ------------------------------------------------------------------------
742. 2018-01-07 01:51:43.111399 [DEBUG] sofia.c:2334 detaching session 412c1118-efb2-4f76-b912-fa6455b7dbf9
743. 2018-01-07 01:51:43.111399 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1001@192.168.22.23) State NEW
744. recv 310 bytes from udp/[192.168.22.122]:5060 at 01:51:43.150767:
745.    ------------------------------------------------------------------------
746.    ACK sip:9664@192.168.22.23 SIP/2.0
747.    Via: SIP/2.0/UDP 192.168.22.122;rport;branch=z9hG4bKsjxiuufv
748.    Max-Forwards: 70
749.    To: <sip:9664@192.168.22.23>;tag=HetKvH2Sy4NUQ
750.    From: "xq1001" <sip:1001@192.168.22.23>;tag=sdofb
751.    Call-ID: hxtpeywcrtubfgu@mx16
752.    CSeq: 720 ACK
753.    User-Agent: Twinkle/1.10.1
754.    Content-Length: 0
755.    
756.    ------------------------------------------------------------------------
757. recv 1038 bytes from udp/[192.168.22.122]:5060 at 01:51:43.151381:
758.    ------------------------------------------------------------------------
759.    INVITE sip:9664@192.168.22.23 SIP/2.0
760.    Via: SIP/2.0/UDP 192.168.22.122;rport;branch=z9hG4bKugrvoxsi
761.    Max-Forwards: 70
762.    Proxy-Authorization: Digest username="1001",realm="192.168.22.23",nonce="e292d3a8-95c8-4233-8f32-042467938893",uri="sip:9664@192.168.22.23",response="506705bfb6087c87c23296671ef7ab84",algorithm=MD5,cnonce="d1c237211e",qop=auth,nc=00000001
763.    To: <sip:9664@192.168.22.23>
764.    From: "xq1001" <sip:1001@192.168.22.23>;tag=sdofb
765.    Call-ID: hxtpeywcrtubfgu@mx16
766.    CSeq: 721 INVITE
767.    Contact: <sip:1001@192.168.22.122>
768.    Content-Type: application/sdp
769.    Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE
770.    Supported: replaces,norefersub,100rel
771.    User-Agent: Twinkle/1.10.1
772.    Content-Length: 312
773.    
774.    v=0
775.    o=twinkle 1321715876 379379822 IN IP4 192.168.22.122
776.    s=-
777.    c=IN IP4 192.168.22.122
778.    t=0 0
779.    m=audio 8000 RTP/AVP 98 97 8 0 3 101
780.    a=rtpmap:98 speex/16000
781.    a=rtpmap:97 speex/8000
782.    a=rtpmap:8 PCMA/8000
783.    a=rtpmap:0 PCMU/8000
784.    a=rtpmap:3 GSM/8000
785.    a=rtpmap:101 telephone-event/8000
786.    a=fmtp:101 0-15
787.    a=ptime:20
788.    ------------------------------------------------------------------------
789. send 317 bytes to udp/[192.168.22.122]:5060 at 01:51:43.152794:
790.    ------------------------------------------------------------------------
791.    SIP/2.0 100 Trying
792.    Via: SIP/2.0/UDP 192.168.22.122;rport=5060;branch=z9hG4bKugrvoxsi
793.    From: "xq1001" <sip:1001@192.168.22.23>;tag=sdofb
794.    To: <sip:9664@192.168.22.23>
795.    Call-ID: hxtpeywcrtubfgu@mx16
796.    CSeq: 721 INVITE
797.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
798.    Content-Length: 0
799.    
800.    ------------------------------------------------------------------------
801. 2018-01-07 01:51:43.151051 [DEBUG] sofia.c:2442 Re-attaching to session 412c1118-efb2-4f76-b912-fa6455b7dbf9
802. 2018-01-07 01:51:43.151051 [DEBUG] sofia.c:9873 sofia/internal/1001@192.168.22.23 receiving invite from 192.168.22.122:5060 version: 1.6.19 git b1b21d0 2017-11-20 16:34:16Z 64bit
803. 2018-01-07 01:51:43.151051 [DEBUG] sofia.c:10044 IP 192.168.22.122 Rejected by acl "domains". Falling back to Digest auth.
804. 2018-01-07 01:51:43.171058 [DEBUG] sofia.c:7084 Channel sofia/internal/1001@192.168.22.23 entering state [received][100]
805. 2018-01-07 01:51:43.171058 [DEBUG] sofia.c:7094 Remote SDP:
806. v=0
807. o=twinkle 1321715876 379379822 IN IP4 192.168.22.122
808. s=-
809. c=IN IP4 192.168.22.122
810. t=0 0
811. m=audio 8000 RTP/AVP 98 97 8 0 3 101
812. a=rtpmap:98 speex/16000
813. a=rtpmap:97 speex/8000
814. a=rtpmap:8 PCMA/8000
815. a=rtpmap:0 PCMU/8000
816. a=rtpmap:3 GSM/8000
817. a=rtpmap:101 telephone-event/8000
818. a=fmtp:101 0-15
819. a=ptime:20
820.  
821. 2018-01-07 01:51:43.171058 [DEBUG] sofia.c:7486 (sofia/internal/1001@192.168.22.23) State Change CS_NEW -> CS_INIT
822. 2018-01-07 01:51:43.171058 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.22.23) Running State Change CS_INIT (Cur 3 Tot 3)
823. 2018-01-07 01:51:43.171058 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.22.23) State INIT
824. 2018-01-07 01:51:43.171058 [DEBUG] mod_sofia.c:90 sofia/internal/1001@192.168.22.23 SOFIA INIT
825. 2018-01-07 01:51:43.171058 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@192.168.22.23 Standard INIT
826. 2018-01-07 01:51:43.171058 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@192.168.22.23) State Change CS_INIT -> CS_ROUTING
827. 2018-01-07 01:51:43.171058 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.22.23) State INIT going to sleep
828. 2018-01-07 01:51:43.171058 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.22.23) Running State Change CS_ROUTING (Cur 3 Tot 3)
829. 2018-01-07 01:51:43.171058 [DEBUG] switch_channel.c:2249 (sofia/internal/1001@192.168.22.23) Callstate Change DOWN -> RINGING
830. 2018-01-07 01:51:43.171058 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.22.23) State ROUTING
831. 2018-01-07 01:51:43.171058 [DEBUG] mod_sofia.c:143 sofia/internal/1001@192.168.22.23 SOFIA ROUTING
832. 2018-01-07 01:51:43.171058 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1001@192.168.22.23 Standard ROUTING
833. 2018-01-07 01:51:43.171058 [INFO] mod_dialplan_xml.c:637 Processing xq1001 <1001>->9664 in context default
834. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->Local_FXS_Extension] continue=false
835. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [Local_FXS_Extension] destination_number(9664) =~ /^(1100)$/ break=on-false
836. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->freetdm.example.com] continue=false
837. Dialplan: sofia/internal/1001@192.168.22.23 Regex (PASS) [freetdm.example.com] ${toll_allow}(domestic,international,local) =~ /local/ break=on-false
838. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [freetdm.example.com] destination_number(9664) =~ /^9(\d{10})$/ break=on-false
839. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->unloop] continue=false
840. Dialplan: sofia/internal/1001@192.168.22.23 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
841. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
842. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->tod_example] continue=true
843. Dialplan: sofia/internal/1001@192.168.22.23 Date/TimeMatch (FAIL) [tod_example] break=on-false
844. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->holiday_example] continue=true
845. Dialplan: sofia/internal/1001@192.168.22.23 Date/TimeMatch (FAIL) [holiday_example] break=on-false
846. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->global-intercept] continue=false
847. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [global-intercept] destination_number(9664) =~ /^886$/ break=on-false
848. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->group-intercept] continue=false
849. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [group-intercept] destination_number(9664) =~ /^\*8$/ break=on-false
850. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->intercept-ext] continue=false
851. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [intercept-ext] destination_number(9664) =~ /^\*\*(\d+)$/ break=on-false
852. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->redial] continue=false
853. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [redial] destination_number(9664) =~ /^(redial|870)$/ break=on-false
854. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->global] continue=true
855. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
856. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [global] ${default_password}(4951) =~ /^1234$/ break=never
857. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
858. Dialplan: sofia/internal/1001@192.168.22.23 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
859. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [global] ${switch_r_sdp}(v=0
860. o=twinkle 1321715876 379379822 IN IP4 192.168.22.122
861. s=-
862. c=IN IP4 192.168.22.122
863. t=0 0
864. m=audio 8000 RTP/AVP 98 97 8 0 3 101
865. a=rtpmap:98 speex/16000
866. a=rtpmap:97 speex/8000
867. a=rtpmap:8 PCMA/8000
868. a=rtpmap:0 PCMU/8000
869. a=rtpmap:3 GSM/8000
870. a=rtpmap:101 telephone-event/8000
871. a=fmtp:101 0-15
872. a=ptime:20
873. ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
874. Dialplan: sofia/internal/1001@192.168.22.23 Absolute Condition [global]
875. Dialplan: sofia/internal/1001@192.168.22.23 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
876. Dialplan: sofia/internal/1001@192.168.22.23 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
877. Dialplan: sofia/internal/1001@192.168.22.23 Action hash(insert/${domain_name}-last_dial/global/${uuid})
878. Dialplan: sofia/internal/1001@192.168.22.23 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
879. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->snom-demo-2] continue=false
880. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [snom-demo-2] destination_number(9664) =~ /^9001$/ break=on-false
881. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->snom-demo-1] continue=false
882. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [snom-demo-1] destination_number(9664) =~ /^9000$/ break=on-false
883. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->eavesdrop] continue=false
884. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [eavesdrop] destination_number(9664) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
885. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->eavesdrop] continue=false
886. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [eavesdrop] destination_number(9664) =~ /^779$/ break=on-false
887. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->call_return] continue=false
888. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [call_return] destination_number(9664) =~ /^\*69$|^869$|^lcr$/ break=on-false
889. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->del-group] continue=false
890. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [del-group] destination_number(9664) =~ /^80(\d{2})$/ break=on-false
891. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->add-group] continue=false
892. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [add-group] destination_number(9664) =~ /^81(\d{2})$/ break=on-false
893. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->call-group-simo] continue=false
894. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [call-group-simo] destination_number(9664) =~ /^82(\d{2})$/ break=on-false
895. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->call-group-order] continue=false
896. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [call-group-order] destination_number(9664) =~ /^83(\d{2})$/ break=on-false
897. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->extension-intercom] continue=false
898. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [extension-intercom] destination_number(9664) =~ /^8(10[01][0-9])$/ break=on-false
899. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->Local_Extension] continue=false
900. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [Local_Extension] destination_number(9664) =~ /^(10[01][0-9])$/ break=on-false
901. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->Local_Extension_Skinny] continue=false
902. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [Local_Extension_Skinny] destination_number(9664) =~ /^(11[01][0-9])$/ break=on-false
903. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->group_dial_sales] continue=false
904. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [group_dial_sales] destination_number(9664) =~ /^2000$/ break=on-false
905. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->group_dial_support] continue=false
906. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [group_dial_support] destination_number(9664) =~ /^2001$/ break=on-false
907. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->group_dial_billing] continue=false
908. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [group_dial_billing] destination_number(9664) =~ /^2002$/ break=on-false
909. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->operator] continue=false
910. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [operator] destination_number(9664) =~ /^(operator|0)$/ break=on-false
911. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->vmain] continue=false
912. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [vmain] destination_number(9664) =~ /^vmain$|^4000$|^\*98$/ break=on-false
913. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->sip_uri] continue=false
914. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [sip_uri] destination_number(9664) =~ /^sip:(.*)$/ break=on-false
915. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->nb_conferences] continue=false
916. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [nb_conferences] destination_number(9664) =~ /^(30\d{2})$/ break=on-false
917. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->wb_conferences] continue=false
918. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [wb_conferences] destination_number(9664) =~ /^(31\d{2})$/ break=on-false
919. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->uwb_conferences] continue=false
920. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [uwb_conferences] destination_number(9664) =~ /^(32\d{2})$/ break=on-false
921. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->cdquality_conferences] continue=false
922. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [cdquality_conferences] destination_number(9664) =~ /^(33\d{2})$/ break=on-false
923. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->cdquality_stereo_conferences] continue=false
924. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [cdquality_stereo_conferences] destination_number(9664) =~ /^(35\d{2}).*?-screen$/ break=on-false
925. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->conference-canvases] continue=true
926. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [conference-canvases] destination_number(9664) =~ /(35\d{2})-canvas-(\d+)/ break=on-false
927. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->conf mod] continue=false
928. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [conf mod] destination_number(9664) =~ /^6070-moderator$/ break=on-false
929. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->cdquality_conferences] continue=false
930. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [cdquality_conferences] destination_number(9664) =~ /^(35\d{2})$/ break=on-false
931. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->freeswitch_public_conf_via_sip] continue=false
932. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(9664) =~ /^9(888|8888|1616|3232)$/ break=on-false
933. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->mad_boss_intercom] continue=false
934. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [mad_boss_intercom] destination_number(9664) =~ /^0911$/ break=on-false
935. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->mad_boss_intercom] continue=false
936. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [mad_boss_intercom] destination_number(9664) =~ /^0912$/ break=on-false
937. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->mad_boss] continue=false
938. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [mad_boss] destination_number(9664) =~ /^0913$/ break=on-false
939. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->ivr_demo] continue=false
940. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [ivr_demo] destination_number(9664) =~ /^5000$/ break=on-false
941. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->dynamic_conference] continue=false
942. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [dynamic_conference] destination_number(9664) =~ /^5001$/ break=on-false
943. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->rtp_multicast_page] continue=false
944. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [rtp_multicast_page] destination_number(9664) =~ /^pagegroup$|^7243$/ break=on-false
945. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->park] continue=false
946. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [park] destination_number(9664) =~ /^5900$/ break=on-false
947. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->unpark] continue=false
948. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [unpark] destination_number(9664) =~ /^5901$/ break=on-false
949. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->valet_park] continue=false
950. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [valet_park] destination_number(9664) =~ /^(6000)$/ break=on-false
951. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->valet_park] continue=false
952. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [valet_park] destination_number(9664) =~ /^((?!6000)60\d{2})$/ break=on-false
953. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->park] continue=false
954. Dialplan: sofia/internal/1001@192.168.22.23 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
955. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [park] destination_number(9664) =~ /park\+(\d+)/ break=on-false
956. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->unpark] continue=false
957. Dialplan: sofia/internal/1001@192.168.22.23 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
958. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [unpark] destination_number(9664) =~ /^parking$/ break=on-false
959. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->park] continue=false
960. Dialplan: sofia/internal/1001@192.168.22.23 Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
961. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [park] destination_number(9664) =~ /callpark/ break=on-false
962. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->unpark] continue=false
963. Dialplan: sofia/internal/1001@192.168.22.23 Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
964. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [unpark] destination_number(9664) =~ /pickup/ break=on-false
965. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->wait] continue=false
966. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [wait] destination_number(9664) =~ /^wait$/ break=on-false
967. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->fax_receive] continue=false
968. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [fax_receive] destination_number(9664) =~ /^9178$/ break=on-false
969. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->fax_transmit] continue=false
970. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [fax_transmit] destination_number(9664) =~ /^9179$/ break=on-false
971. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->ringback_180] continue=false
972. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [ringback_180] destination_number(9664) =~ /^9180$/ break=on-false
973. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->ringback_183_uk_ring] continue=false
974. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [ringback_183_uk_ring] destination_number(9664) =~ /^9181$/ break=on-false
975. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->ringback_183_music_ring] continue=false
976. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [ringback_183_music_ring] destination_number(9664) =~ /^9182$/ break=on-false
977. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->ringback_post_answer_uk_ring] continue=false
978. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [ringback_post_answer_uk_ring] destination_number(9664) =~ /^9183$/ break=on-false
979. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->ringback_post_answer_music] continue=false
980. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [ringback_post_answer_music] destination_number(9664) =~ /^9184$/ break=on-false
981. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->ClueCon] continue=false
982. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [ClueCon] destination_number(9664) =~ /^9191$/ break=on-false
983. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->show_info] continue=false
984. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [show_info] destination_number(9664) =~ /^9192$/ break=on-false
985. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->video_record] continue=false
986. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [video_record] destination_number(9664) =~ /^9193$/ break=on-false
987. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->video_playback] continue=false
988. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [video_playback] destination_number(9664) =~ /^9194$/ break=on-false
989. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->delay_echo] continue=false
990. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [delay_echo] destination_number(9664) =~ /^9195$/ break=on-false
991. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->echo] continue=false
992. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [echo] destination_number(9664) =~ /^9196$/ break=on-false
993. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->milliwatt] continue=false
994. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [milliwatt] destination_number(9664) =~ /^9197$/ break=on-false
995. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->tone_stream] continue=false
996. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [tone_stream] destination_number(9664) =~ /^9198$/ break=on-false
997. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->zrtp_enrollement] continue=false
998. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [zrtp_enrollement] destination_number(9664) =~ /^9787$/ break=on-false
999. Dialplan: sofia/internal/1001@192.168.22.23 parsing [default->hold_music] continue=false
1000. Dialplan: sofia/internal/1001@192.168.22.23 Regex (PASS) [hold_music] destination_number(9664) =~ /^9664$/ break=on-false
1001. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [hold_music] ${rtp_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=on-false
1002. Dialplan: sofia/internal/1001@192.168.22.23 ANTI-Action set(zrtp_secure_media=true)
1003. Dialplan: sofia/internal/1001@192.168.22.23 ANTI-Action answer()
1004. Dialplan: sofia/internal/1001@192.168.22.23 ANTI-Action playback(silence_stream://2000)
1005. Dialplan: sofia/internal/1001@192.168.22.23 ANTI-Action execute_extension(is_zrtp_secure XML features)
1006. Dialplan: sofia/internal/1001@192.168.22.23 ANTI-Action playback(local_stream://moh)
1007. 2018-01-07 01:51:43.191051 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1001@192.168.22.23) State Change CS_ROUTING -> CS_EXECUTE
1008. 2018-01-07 01:51:43.191051 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.22.23) State ROUTING going to sleep
1009. 2018-01-07 01:51:43.191051 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.22.23) Running State Change CS_EXECUTE (Cur 3 Tot 3)
1010. 2018-01-07 01:51:43.191051 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.22.23) State EXECUTE
1011. 2018-01-07 01:51:43.191051 [DEBUG] mod_sofia.c:198 sofia/internal/1001@192.168.22.23 SOFIA EXECUTE
1012. 2018-01-07 01:51:43.191051 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1001@192.168.22.23 Standard EXECUTE
1013. EXECUTE sofia/internal/1001@192.168.22.23 hash(insert/192.168.22.23-spymap/1001/412c1118-efb2-4f76-b912-fa6455b7dbf9)
1014. EXECUTE sofia/internal/1001@192.168.22.23 hash(insert/192.168.22.23-last_dial/1001/9664)
1015. EXECUTE sofia/internal/1001@192.168.22.23 hash(insert/192.168.22.23-last_dial/global/412c1118-efb2-4f76-b912-fa6455b7dbf9)
1016. EXECUTE sofia/internal/1001@192.168.22.23 export(RFC2822_DATE=Sun, 07 Jan 2018 01:51:43 -0600)
1017. 2018-01-07 01:51:43.211074 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Sun, 07 Jan 2018 01:51:43 -0600]
1018. EXECUTE sofia/internal/1001@192.168.22.23 set(zrtp_secure_media=true)
1019. 2018-01-07 01:51:43.211074 [DEBUG] mod_dptools.c:1548 SET sofia/internal/1001@192.168.22.23 [zrtp_secure_media]=[true]
1020. EXECUTE sofia/internal/1001@192.168.22.23 answer()
1021. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[opus:116:48000:20:0:1]
1022. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[G722:9:8000:20:64000:1]
1023. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
1024. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
1025. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[opus:116:48000:20:0:1]
1026. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[G722:9:8000:20:64000:1]
1027. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
1028. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
1029. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
1030. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
1031. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
1032. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1033. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
1034. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
1035. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
1036. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
1037. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
1038. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
1039. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
1040. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
1041. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
1042. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
1043. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
1044. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/1001@192.168.22.23 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
1045. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@192.168.22.23 Original read codec set to PCMA:8
1046. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
1047. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:4767 sofia/internal/1001@192.168.22.23 Set 2833 dtmf send payload to 101 recv payload to 101
1048. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/1001@192.168.22.23] 192.168.22.23 port 31882 -> 192.168.22.122 port 8000 codec: 8 ms: 20
1049. 2018-01-07 01:51:43.211074 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
1050. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:7180 sofia/internal/1001@192.168.22.23 Set 2833 dtmf send payload to 101
1051. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:7187 sofia/internal/1001@192.168.22.23 Set 2833 dtmf receive payload to 101
1052. 2018-01-07 01:51:43.211074 [DEBUG] switch_core_media.c:7210 sofia/internal/1001@192.168.22.23 Set rtp dtmf delay to 40
1053. 2018-01-07 01:51:43.211074 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1001@192.168.22.23!
1054. 2018-01-07 01:51:43.211074 [DEBUG] switch_channel.c:3474 (sofia/internal/1001@192.168.22.23) Callstate Change RINGING -> EARLY
1055. 2018-01-07 01:51:43.231045 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/1001@192.168.22.23.
1056. 2018-01-07 01:51:43.231045 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/1001@192.168.22.23:
1057. v=0
1058. o=FreeSWITCH 1515279621 1515279622 IN IP4 192.168.22.23
1059. s=FreeSWITCH
1060. c=IN IP4 192.168.22.23
1061. t=0 0
1062. m=audio 31882 RTP/AVP 8 101
1063. a=rtpmap:8 PCMA/8000
1064. a=rtpmap:101 telephone-event/8000
1065. a=fmtp:101 0-16
1066. a=ptime:20
1067. a=sendrecv
1068.  
1069. send 1096 bytes to udp/[192.168.22.122]:5060 at 01:51:43.233937:
1070.    ------------------------------------------------------------------------
1071.    SIP/2.0 200 OK
1072.    Via: SIP/2.0/UDP 192.168.22.122;rport=5060;branch=z9hG4bKugrvoxsi
1073.    From: "xq1001" <sip:1001@192.168.22.23>;tag=sdofb
1074.    To: <sip:9664@192.168.22.23>;tag=jQKcycKXUDceK
1075.    Call-ID: hxtpeywcrtubfgu@mx16
1076.    CSeq: 721 INVITE
1077.    Contact: <sip:9664@192.168.22.23:5060;transport=udp>
1078.    User-Agent: FreeSWITCH-mod_sofia/1.6.19+git~20171120T163416Z~b1b21d0695~64bit
1079.    Accept: application/sdp
1080.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1081.    Supported: timer, path, replaces
1082.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1083.    Content-Type: application/sdp
1084.    Content-Disposition: session
1085.    Content-Length: 222
1086.    Remote-Party-ID: "9664" <sip:9664@192.168.22.23>;party=calling;privacy=off;screen=no
1087.    
1088.    v=0
1089.    o=FreeSWITCH 1515279621 1515279622 IN IP4 192.168.22.23
1090.    s=FreeSWITCH
1091.    c=IN IP4 192.168.22.23
1092.    t=0 0
1093.    m=audio 31882 RTP/AVP 8 101
1094.    a=rtpmap:8 PCMA/8000
1095.    a=rtpmap:101 telephone-event/8000
1096.    a=fmtp:101 0-16
1097.    a=ptime:20
1098.    ------------------------------------------------------------------------
1099. 2018-01-07 01:51:43.231045 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/1001@192.168.22.23] has been answered
1100. 2018-01-07 01:51:43.231045 [DEBUG] switch_channel.c:3773 (sofia/internal/1001@192.168.22.23) Callstate Change EARLY -> ACTIVE
1101. 2018-01-07 01:51:43.231045 [DEBUG] sofia.c:7084 Channel sofia/internal/1001@192.168.22.23 entering state [completed][200]
1102. EXECUTE sofia/internal/1001@192.168.22.23 playback(silence_stream://2000)
1103. 2018-01-07 01:51:43.231045 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
1104. recv 569 bytes from udp/[192.168.22.122]:5060 at 01:51:43.252086:
1105.    ------------------------------------------------------------------------
1106.    ACK sip:9664@192.168.22.23:5060;transport=udp SIP/2.0
1107.    Via: SIP/2.0/UDP 192.168.22.122;rport;branch=z9hG4bKdiperioq
1108.    Max-Forwards: 70
1109.    Proxy-Authorization: Digest username="1001",realm="192.168.22.23",nonce="e292d3a8-95c8-4233-8f32-042467938893",uri="sip:9664@192.168.22.23",response="506705bfb6087c87c23296671ef7ab84",algorithm=MD5,cnonce="d1c237211e",qop=auth,nc=00000001
1110.    To: <sip:9664@192.168.22.23>;tag=jQKcycKXUDceK
1111.    From: "xq1001" <sip:1001@192.168.22.23>;tag=sdofb
1112.    Call-ID: hxtpeywcrtubfgu@mx16
1113.    CSeq: 721 ACK
1114.    User-Agent: Twinkle/1.10.1
1115.    Content-Length: 0
1116.    
1117.    ------------------------------------------------------------------------
1118. 2018-01-07 01:51:43.251043 [DEBUG] sofia.c:7084 Channel sofia/internal/1001@192.168.22.23 entering state [ready][200]
1119. 2018-01-07 01:51:43.331026 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
1120. 2018-01-07 01:51:45.211035 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://2000
1121. EXECUTE sofia/internal/1001@192.168.22.23 execute_extension(is_zrtp_secure XML features)
1122. 2018-01-07 01:51:45.211035 [INFO] mod_dialplan_xml.c:637 Processing xq1001 <1001>->is_zrtp_secure in context features
1123. Dialplan: sofia/internal/1001@192.168.22.23 parsing [features->dx] continue=false
1124. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [dx] destination_number(is_zrtp_secure) =~ /^dx$/ break=on-false
1125. Dialplan: sofia/internal/1001@192.168.22.23 parsing [features->att_xfer] continue=false
1126. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [att_xfer] destination_number(is_zrtp_secure) =~ /^att_xfer$/ break=on-false
1127. Dialplan: sofia/internal/1001@192.168.22.23 parsing [features->is_transfer] continue=false
1128. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [is_transfer] destination_number(is_zrtp_secure) =~ /^is_transfer$/ break=on-false
1129. Dialplan: sofia/internal/1001@192.168.22.23 parsing [features->cf] continue=false
1130. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [cf] destination_number(is_zrtp_secure) =~ /^cf$/ break=on-false
1131. Dialplan: sofia/internal/1001@192.168.22.23 parsing [features->please_hold] continue=false
1132. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [please_hold] destination_number(is_zrtp_secure) =~ /^(10[01][0-9])$/ break=on-false
1133. Dialplan: sofia/internal/1001@192.168.22.23 parsing [features->is_zrtp_secure] continue=true
1134. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false
1135. Dialplan: sofia/internal/1001@192.168.22.23 ANTI-Action eval(not_secure)
1136. Dialplan: sofia/internal/1001@192.168.22.23 parsing [features->is_secure] continue=true
1137. Dialplan: sofia/internal/1001@192.168.22.23 Regex (FAIL) [is_secure] ${sip_via_protocol}(udp) =~ /tls/ break=on-false
1138. 2018-01-07 01:51:45.211035 [NOTICE] switch_core_session.c:2914 Execute eval(not_secure)
1139. EXECUTE sofia/internal/1001@192.168.22.23 eval(not_secure)
1140. EXECUTE sofia/internal/1001@192.168.22.23 playback(local_stream://moh)
1141. 2018-01-07 01:51:45.231039 [DEBUG] mod_local_stream.c:871 Opening Stream [moh/8000] 8000hz
1142. 2018-01-07 01:51:45.231039 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
1143.