1. root@fpbx01:~# fs_cli
2. .=======================================================.
3. |            _____ ____     ____ _     ___              |
4. |           |  ___/ ___|   / ___| |   |_ _|             |
5. |           | |_  \___ \  | |   | |    | |              |
6. |           |  _|  ___) | | |___| |___ | |              |
7. |           |_|   |____/   \____|_____|___|             |
8. |                                                       |
9. .=======================================================.
10. | Anthony Minessale II, Ken Rice,                       |
11. | Michael Jerris, Travis Cross                          |
12. | FreeSWITCH (http://www.freeswitch.org)                |
13. | Paypal Donations Appreciated: paypal@freeswitch.org   |
14. | Brought to you by ClueCon http://www.cluecon.com/     |
15. .=======================================================.
16.  
17. .=======================================================================================================.
18. |       _                            _    ____ _             ____                                       |
19. |      / \   _ __  _ __  _   _  __ _| |  / ___| |_   _  ___ / ___|___  _ __                             |
20. |     / _ \ | '_ \| '_ \| | | |/ _` | | | |   | | | | |/ _ \ |   / _ \| '_ \                            |
21. |    / ___ \| | | | | | | |_| | (_| | | | |___| | |_| |  __/ |__| (_) | | | |                           |
22. |   /_/   \_\_| |_|_| |_|\__,_|\__,_|_|  \____|_|\__,_|\___|\____\___/|_| |_|                           |
23. |                                                                                                       |
24. |    ____ _____ ____    ____             __                                                             |
25. |   |  _ \_   _/ ___|  / ___|___  _ __  / _| ___ _ __ ___ _ __   ___ ___                                |
26. |   | |_) || || |     | |   / _ \| '_ \| |_ / _ \ '__/ _ \ '_ \ / __/ _ \                               |
27. |   |  _ < | || |___  | |__| (_) | | | |  _|  __/ | |  __/ | | | (_|  __/                               |
28. |   |_| \_\|_| \____|  \____\___/|_| |_|_|  \___|_|  \___|_| |_|\___\___|                               |
29. |                                                                                                       |
30. |     ____ _             ____                                                                           |
31. |    / ___| |_   _  ___ / ___|___  _ __         ___ ___  _ __ ___                                       |
32. |   | |   | | | | |/ _ \ |   / _ \| '_ \       / __/ _ \| '_ ` _ \                                      |
33. |   | |___| | |_| |  __/ |__| (_) | | | |  _  | (_| (_) | | | | | |                                     |
34. |    \____|_|\__,_|\___|\____\___/|_| |_| (_)  \___\___/|_| |_| |_|                                     |
35. |                                                                                                       |
36. .=======================================================================================================.
37.  
38. Type /help <enter> to see a list of commands
39.  
40.  
41.  
42. +OK log level  [7]
43. freeswitch@fpbx01> hello
44. -ERR hello Command not found!
45.  
46. freeswitch@fpbx01> sofia loglevel all 9
47. Sofia log level for component [all] has been set to [9]
48. freeswitch@fpbx01> sofia global siptrace on
49. +OK Global siptrace on
50. nua.c:575 nua_set_params() nua: nua_set_params: entering
51. freeswitch@fpbx01>
52. nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
53. freeswitch@fpbx01>
54. nua.c:575 nua_set_params() nua: nua_set_params: entering
55. freeswitch@fpbx01>
56. nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
57. freeswitch@fpbx01>
58. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
59. freeswitch@fpbx01>
60. nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
61. freeswitch@fpbx01>
62. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
63. freeswitch@fpbx01>
64. soa.c:403 soa_set_params() soa_set_params(static::0x7fce54084150, ...) called
65. freeswitch@fpbx01>
66. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74005a30, ...) called
67. freeswitch@fpbx01>
68. nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
69. freeswitch@fpbx01>
70. nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
71. freeswitch@fpbx01>
72. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
73. freeswitch@fpbx01>
74. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
75. freeswitch@fpbx01>
76. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
77. freeswitch@fpbx01>
78. nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
79. freeswitch@fpbx01>
80. nua.c:575 nua_set_params() nua: nua_set_params: entering
81. freeswitch@fpbx01>
82. nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
83. freeswitch@fpbx01>
84. nua.c:575 nua_set_params() nua: nua_set_params: entering
85. freeswitch@fpbx01>
86. nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
87. freeswitch@fpbx01>
88. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
89. freeswitch@fpbx01>
90. soa.c:403 soa_set_params() soa_set_params(static::0x7fce40001930, ...) called
91. freeswitch@fpbx01>
92. nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
93. freeswitch@fpbx01>
94. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
95. freeswitch@fpbx01>
96. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60096e10, ...) called
97. freeswitch@fpbx01>
98. nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
99. freeswitch@fpbx01>
100. nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
101. freeswitch@fpbx01>
102. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
103. freeswitch@fpbx01>
104. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
105. freeswitch@fpbx01>
106. nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
107. freeswitch@fpbx01>
108. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
109. freeswitch@fpbx01>
110. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
111. freeswitch@fpbx01>
112. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
113. freeswitch@fpbx01>
114. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
115. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
116. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 4
117. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 4 bytes, veclen = 1
118. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
119. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN
120. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50)
121. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 4
122. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 4 bytes, veclen = 1
123. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
124. freeswitch@fpbx01>
125. freeswitch@fpbx01>
126. freeswitch@fpbx01>
127. nta.c:1296 agent_timer() nta: timer set next to 6609 ms
128. nta.c:9107 outgoing_timer_dk() nta: timer D fired, terminate INVITE (5318782)
129. nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fce6b73ed30)
130. nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/1 term, 1/2 free
131. nta.c:1296 agent_timer() nta: timer set next to 1 ms
132. nta.c:8988 outgoing_timer_bf() nta: timer F fired, terminating ACK (5318782)
133. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
134. nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fce6b73ed30)
135. nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 1/1 free
136. nta.c:1289 agent_timer() nta: timer not set
137. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
138. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
139. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 4
140. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 4 bytes, veclen = 1
141. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
142. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
143. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
144. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 1248 bytes, veclen = 1
145. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
146. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
147. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
148. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 259 bytes, veclen = 1
149. recv 1507 bytes from tcp/[10.55.4.5]:55848 at 15:33:16.358341:
150.    ------------------------------------------------------------------------
151.    INVITE sip:7667398@10.55.4.7:5080 SIP/2.0
152.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f
153.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
154.    To: <sip:7667398@10.55.4.7>
155.    Date: Wed, 05 Jun 2019 14:33:16 GMT
156.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
157.    Supported: timer,resource-priority,replaces
158.    Min-SE:  1800
159.    User-Agent: Cisco-CUCM10.5
160.   Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
161.    CSeq: 101 INVITE
162.    Expires: 180
163.    Allow-Events: presence, kpml
164.    Supported: X-cisco-srtp-fallback,X-cisco-original-called
165.    Call-Info: <sip:10.55.4.5:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
166.    Call-Info: <urn:x-cisco-remotecc:callinfo>;x-cisco-video-traffic-class=VIDEO_UNSPECIFIED
167.    Cisco-Guid: 3653460864-0000065536-0000003112-0084162314
168.    Session-Expires:  1800
169.    P-Asserted-Identity: "Stephen Barry" <sip:7398@10.55.4.5>
170.    Remote-Party-ID: "Stephen Barry" <sip:7398@10.55.4.5>;party=calling;screen=yes;privacy=off
171.    Contact: <sip:7398@10.55.4.5:5060;transport=tcp>
172.    Max-Forwards: 70
173.    Content-Type: application/sdp
174.    Content-Length: 360
175.  
176.    v=0
177.    o=CiscoSystemsCCM-SIP 3080835 1 IN IP4 10.55.4.5
178.    s=SIP Call
179.    c=IN IP4 10.55.102.51
180.    b=TIAS:64000
181.    b=AS:64
182.    t=0 0
183.    m=audio 16670 RTP/AVP 9 8 0 116 18 101
184.    a=rtpmap:9 G722/8000
185.    a=rtpmap:8 PCMA/8000
186.    a=rtpmap:0 PCMU/8000
187.    a=rtpmap:116 iLBC/8000
188.    a=maxptime:60
189.    a=fmtp:116 mode=20
190.    a=rtpmap:18 G729/8000
191.    a=rtpmap:101 telephone-event/8000
192.    a=fmtp:101 0-15
193.    ------------------------------------------------------------------------
194. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74008dc0 (1507 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
195. nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080 SIP/2.0 (CSeq 101)
196. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
197. nta.c:3085 agent_recv_request() nta: INVITE (101) going to a default leg
198. nta.c:1350 set_timeout() nta: timer set to 2000 ms
199. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
200. nua_stack.c:899 nh_create() nua: nh_create: entering
201. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
202. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
203. soa.c:280 soa_clone() soa_clone(static::0x7fce74005a30, 0x7fce7400d770, 0x7fce74002fd0) called
204. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
205. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fce740033f0)
206. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called
207. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce74014690, (nil), 0x7fce74003a9b, 360) called
208. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce74002fd0): adding session usage
209. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying
210. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: init -> received, received offer
211. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce74014690, [0x7fce6b5ea8d8], [0x7fce6b5ea8e0], [(nil)]) called
212. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying
213. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
214. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
215. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
216. 2019-06-05 15:33:16.509165 [NOTICE] switch_channel.c:1104 New Channel sofia/external-lan/7398@10.55.4.5 [6efa6b88-248e-4a15-afca-09df2beb867e]
217. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
218. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_NEW (Cur 1 Tot 313)
219. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
220. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:10092 sofia/external-lan/7398@10.55.4.5 receiving invite from 10.55.4.5:55848 version: 1.8.5 -6-31281a0bf1 64bit
221. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:10208 IP 10.55.4.5 Approved by acl "domains[]". Access Granted.
222. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
223. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
224. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100]
225. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7301 Remote SDP:
226. v=0
227. o=CiscoSystemsCCM-SIP 3080835 1 IN IP4 10.55.4.5
228. s=SIP Call
229. c=IN IP4 10.55.102.51
230. b=TIAS:64000
231. b=AS:64
232. t=0 0
233. m=audio 16670 RTP/AVP 9 8 0 116 18 101
234. a=rtpmap:9 G722/8000
235. a=rtpmap:8 PCMA/8000
236. a=rtpmap:0 PCMU/8000
237. a=rtpmap:116 iLBC/8000
238. a=fmtp:116 mode=20
239. a=rtpmap:18 G729/8000
240. a=rtpmap:101 telephone-event/8000
241. a=fmtp:101 0-15
242. a=maxptime:60
243.  
244. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
245. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
246. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
247. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[G722:9:8000:20:64000:1]
248. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
249. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
250. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
251. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
252. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
253. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
254. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G722:9:8000:20:64000:1]
255. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
256. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
257. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
258. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
259. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
260. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
261. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G722:9:8000:20:64000:1]
262. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
263. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
264. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
265. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
266. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
267. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
268. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[G722:9:8000:20:64000:1]
269. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMA:8:8000:20:64000:1]
270. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMU:0:8000:20:64000:1]
271. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
272. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
273. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
274. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[G722:9:8000:20:64000:1]
275. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMA:8:8000:20:64000:1]
276. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMU:0:8000:20:64000:1]
277. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
278. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:3781 Set Codec sofia/external-lan/7398@10.55.4.5 G722/8000 20 ms 160 samples 64000 bits 1 channels
279. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_codec.c:111 sofia/external-lan/7398@10.55.4.5 Original read codec set to G722:9
280. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
281. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_media.c:5795 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101 recv payload to 101
282. 2019-06-05 15:33:16.509165 [DEBUG] sofia.c:7716 (sofia/external-lan/7398@10.55.4.5) State Change CS_NEW -> CS_INIT
283. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
284. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:603 (sofia/external-lan/7398@10.55.4.5) State NEW
285. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_INIT (Cur 1 Tot 313)
286. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:627 (sofia/external-lan/7398@10.55.4.5) State INIT
287. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:93 sofia/external-lan/7398@10.55.4.5 SOFIA INIT
288. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:40 sofia/external-lan/7398@10.55.4.5 Standard INIT
289. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:48 (sofia/external-lan/7398@10.55.4.5) State Change CS_INIT -> CS_ROUTING
290. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:627 (sofia/external-lan/7398@10.55.4.5) State INIT going to sleep
291. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_ROUTING (Cur 1 Tot 313)
292. 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:2249 (sofia/external-lan/7398@10.55.4.5) Callstate Change DOWN -> RINGING
293. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING
294. nua.c:879 nua_respond() nua: nua_respond: entering
295. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 100 Trying
296. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
297. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
298. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
299. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
300. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:154 sofia/external-lan/7398@10.55.4.5 SOFIA ROUTING
301. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:236 sofia/external-lan/7398@10.55.4.5 Standard ROUTING
302. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 337 bytes of 337 to tcp/10.55.4.5:55848
303. tport.c:3496 tport_send_msg() tport_vsend returned 337
304. 2019-06-05 15:33:16.509165 [INFO] mod_dialplan_xml.c:637 Processing Stephen Barry <7398>->7667398 in context public
305. send 337 bytes to tcp/[10.55.4.5]:55848 at 15:33:16.359409:
306.    ------------------------------------------------------------------------
307.    SIP/2.0 100 Trying
308.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848
309.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
310.    To: <sip:7667398@10.55.4.7>
311.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
312.    CSeq: 101 INVITE
313.    User-Agent: FreeSWITCH
314.    Content-Length: 0
315.  
316.    ------------------------------------------------------------------------
317. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
318. nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (101)
319. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [public->caller-details] continue=true
320. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [caller-details] () =~ // break=never
321. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(call_direction=inbound) INLINE
322. EXECUTE sofia/external-lan/7398@10.55.4.5 export(call_direction=inbound)
323. 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound]
324. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_destination=${destination_number}) INLINE
325. EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_destination=7667398)
326. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_destination]=[7667398]
327. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_id_name=${caller_id_name}) INLINE
328. EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_id_name=Stephen Barry)
329. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_id_name]=[Stephen Barry]
330. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(caller_id_number=${caller_id_number})
331. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [public->7667398] continue=false
332. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [7667398] destination_number(7667398) =~ /^(7667398)$/ break=on-false
333. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(call_direction=inbound) INLINE
334. EXECUTE sofia/external-lan/7398@10.55.4.5 export(call_direction=inbound)
335. 2019-06-05 15:33:16.509165 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[inbound]
336. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(domain_uuid=4772272a-5245-454d-8520-d9e852b4c5a2) INLINE
337. EXECUTE sofia/external-lan/7398@10.55.4.5 set(domain_uuid=4772272a-5245-454d-8520-d9e852b4c5a2)
338. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [domain_uuid]=[4772272a-5245-454d-8520-d9e852b4c5a2]
339. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(domain_name=voip.mydomain.com) INLINE
340. EXECUTE sofia/external-lan/7398@10.55.4.5 set(domain_name=voip.mydomain.com)
341. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [domain_name]=[voip.mydomain.com]
342. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hangup_after_bridge=true)
343. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(continue_on_fail=true)
344. Dialplan: sofia/external-lan/7398@10.55.4.5 Action transfer(7667398 XML voip.mydomain.com)
345. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:286 (sofia/external-lan/7398@10.55.4.5) State Change CS_ROUTING -> CS_EXECUTE
346. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING going to sleep
347. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_EXECUTE (Cur 1 Tot 313)
348. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE
349. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:209 sofia/external-lan/7398@10.55.4.5 SOFIA EXECUTE
350. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:328 sofia/external-lan/7398@10.55.4.5 Standard EXECUTE
351. EXECUTE sofia/external-lan/7398@10.55.4.5 set(caller_id_number=7398)
352. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [caller_id_number]=[7398]
353. EXECUTE sofia/external-lan/7398@10.55.4.5 set(hangup_after_bridge=true)
354. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hangup_after_bridge]=[true]
355. EXECUTE sofia/external-lan/7398@10.55.4.5 set(continue_on_fail=true)
356. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [continue_on_fail]=[true]
357. EXECUTE sofia/external-lan/7398@10.55.4.5 transfer(7667398 XML voip.mydomain.com)
358. 2019-06-05 15:33:16.509165 [DEBUG] switch_ivr.c:2207 (sofia/external-lan/7398@10.55.4.5) State Change CS_EXECUTE -> CS_ROUTING
359. 2019-06-05 15:33:16.509165 [NOTICE] switch_ivr.c:2214 Transfer sofia/external-lan/7398@10.55.4.5 to XML[7667398@voip.mydomain.com]
360. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE going to sleep
361. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_ROUTING (Cur 1 Tot 313)
362. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING
363. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged
364. 2019-06-05 15:33:16.509165 [DEBUG] mod_sofia.c:154 sofia/external-lan/7398@10.55.4.5 SOFIA ROUTING
365. 2019-06-05 15:33:16.509165 [DEBUG] switch_core_state_machine.c:236 sofia/external-lan/7398@10.55.4.5 Standard ROUTING
366. 2019-06-05 15:33:16.509165 [INFO] mod_dialplan_xml.c:637 Processing Stephen Barry <7398>->7667398 in context voip.mydomain.com
367. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->user_exists] continue=true
368. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_exists] () =~ // break=on-false
369. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
370. EXECUTE sofia/external-lan/7398@10.55.4.5 set(user_exists=true)
371. 2019-06-05 15:33:16.509165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [user_exists]=[true]
372. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
373. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
374. EXECUTE sofia/external-lan/7398@10.55.4.5 set(extension_uuid=d268f1c9-32b4-46c7-8c22-74012c9929ac)
375. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [extension_uuid]=[d268f1c9-32b4-46c7-8c22-74012c9929ac]
376. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
377. EXECUTE sofia/external-lan/7398@10.55.4.5 set(hold_music=)
378. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hold_music]=[UNDEF]
379. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
380. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_enabled=)
381. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_enabled]=[UNDEF]
382. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
383. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_destination=)
384. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_destination]=[UNDEF]
385. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
386. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_busy_enabled=)
387. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_busy_enabled]=[UNDEF]
388. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
389. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_busy_destination=)
390. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_busy_destination]=[UNDEF]
391. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
392. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_no_answer_enabled=)
393. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_no_answer_enabled]=[UNDEF]
394. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
395. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_no_answer_destination=)
396. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_no_answer_destination]=[UNDEF]
397. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
398. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_user_not_registered_enabled=)
399. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_user_not_registered_enabled]=[UNDEF]
400. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
401. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_user_not_registered_destination=)
402. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_user_not_registered_destination]=[UNDEF]
403. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
404. EXECUTE sofia/external-lan/7398@10.55.4.5 set(forward_all_enabled=)
405. 2019-06-05 15:33:16.529171 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [forward_all_enabled]=[UNDEF]
406. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
407. EXECUTE sofia/external-lan/7398@10.55.4.5 set(do_not_disturb=)
408. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [do_not_disturb]=[UNDEF]
409. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
410. EXECUTE sofia/external-lan/7398@10.55.4.5 set(call_timeout=30)
411. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [call_timeout]=[30]
412. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
413. EXECUTE sofia/external-lan/7398@10.55.4.5 set(missed_call_app=)
414. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [missed_call_app]=[UNDEF]
415. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
416. EXECUTE sofia/external-lan/7398@10.55.4.5 set(missed_call_data=)
417. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [missed_call_data]=[UNDEF]
418. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
419. EXECUTE sofia/external-lan/7398@10.55.4.5 set(toll_allow=)
420. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [toll_allow]=[UNDEF]
421. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
422. EXECUTE sofia/external-lan/7398@10.55.4.5 set(call_screen_enabled=false)
423. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [call_screen_enabled]=[false]
424. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
425. EXECUTE sofia/external-lan/7398@10.55.4.5 set(user_record=)
426. 2019-06-05 15:33:16.549165 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [user_record]=[UNDEF]
427. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->caller-details] continue=true
428. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [caller-details] ${caller_destination}(7667398) =~ /^$/ break=never
429. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call-direction] continue=true
430. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
431. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->variables] continue=true
432. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [variables] () =~ // break=on-false
433. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(origination_callee_id_name=${destination_number})
434. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
435. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->user_record] continue=true
436. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] () =~ // break=on-false
437. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
438. EXECUTE sofia/external-lan/7398@10.55.4.5 set(from_user_exists=false)
439. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [from_user_exists]=[false]
440. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
441. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
442. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
443. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
444. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
445. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
446. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
447. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
448. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
449. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
450. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
451. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
452. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
453. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
454. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
455. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
456. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
457. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
458. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
459. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
460. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
461. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
462. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
463. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
464. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->redial] continue=true
465. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [redial] destination_number(7667398) =~ /^(redial|\*870)$/ break=on-true
466. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [redial] () =~ // break=never
467. Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
468. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->speed_dial] continue=false
469. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [speed_dial] destination_number(7667398) =~ /^\*0(.*)$/ break=on-false
470. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->default_caller_id] continue=true
471. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
472. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
473. EXECUTE sofia/external-lan/7398@10.55.4.5 set(emergency_caller_id_name=)
474. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [emergency_caller_id_name]=[UNDEF]
475. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
476. EXECUTE sofia/external-lan/7398@10.55.4.5 set(emergency_caller_id_number=)
477. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [emergency_caller_id_number]=[UNDEF]
478. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never
479. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
480. EXECUTE sofia/external-lan/7398@10.55.4.5 set(outbound_caller_id_name=)
481. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [outbound_caller_id_name]=[UNDEF]
482. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE
483. EXECUTE sofia/external-lan/7398@10.55.4.5 set(outbound_caller_id_number=)
484. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [outbound_caller_id_number]=[UNDEF]
485. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.d4] continue=false
486. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.d4] ${user_exists}(true) =~ /false/ break=on-false
487. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.11] continue=false
488. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.11] ${user_exists}(true) =~ /false/ break=on-false
489. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.11] continue=false
490. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.11] ${user_exists}(true) =~ /false/ break=on-false
491. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->bxrp-ln5-cucm02.uk.local.10.05800] continue=false
492. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [bxrp-ln5-cucm02.uk.local.10.05800] ${user_exists}(true) =~ /false/ break=on-false
493. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->agent_status] continue=false
494. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [agent_status] destination_number(7667398) =~ /^\*22$/ break=on-false
495. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->agent_status_id] continue=false
496. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [agent_status_id] destination_number(7667398) =~ /^\*23$/ break=on-false
497. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->group-intercept] continue=false
498. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [group-intercept] destination_number(7667398) =~ /^\*8$/ break=on-false
499. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->page-extension] continue=false
500. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [page-extension] destination_number(7667398) =~ /^\*8(\d{2,7})$/ break=on-false
501. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->eavesdrop] continue=false
502. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [eavesdrop] destination_number(7667398) =~ /^\*33(\d{2,7})$/ break=on-false
503. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_privacy] continue=false
504. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_privacy] destination_number(7667398) =~ /^\*67(\d+)$/ break=on-false
505. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_return] continue=false
506. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_return] destination_number(7667398) =~ /^\*69$/ break=on-false
507. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->intercept-ext-polycom] continue=false
508. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext-polycom] destination_number(7667398) =~ /^\*97(\d+)$/ break=on-false
509. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->intercept-ext] continue=false
510. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext] destination_number(7667398) =~ /^\*\*(\d+)$/ break=on-true
511. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [intercept-ext] destination_number(7667398) =~ /^\*\*$/ break=on-false
512. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->extension_queue] continue=false
513. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [extension_queue] destination_number(7667398) =~ /^\*800(.*)$/ break=on-false
514. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->dx] continue=false
515. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [dx] destination_number(7667398) =~ /^dx$/ break=on-false
516. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->att_xfer] continue=false
517. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [att_xfer] destination_number(7667398) =~ /^att_xfer$/ break=on-false
518. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->send_to_voicemail] continue=false
519. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [send_to_voicemail] destination_number(7667398) =~ /^\*99(\d{2,10})$/ break=on-false
520. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->extension-to-voicemail] continue=false
521. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false
522. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [extension-to-voicemail] username(7398) =~ /^7398$/ break=on-false
523. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [extension-to-voicemail] destination_number(7667398) =~ /^7398$/ break=on-false
524. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->xfer_vm] continue=false
525. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [xfer_vm] destination_number(7667398) =~ /^xfer_vm$/ break=on-false
526. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->vmain] continue=false
527. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain] destination_number(7667398) =~ /^vmain$|^\*4000$|^\*98$/ break=never
528. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain] destination_number(7667398) =~ /^(vmain$|^\*4000$|^\*98)(\d{2,12})$/ break=on-false
529. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->vmain_user] continue=false
530. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [vmain_user] destination_number(7667398) =~ /^\*97$/ break=on-false
531. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_transfer] continue=false
532. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_transfer] destination_number(7667398) =~ /^is_transfer$/ break=on-false
533. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->delay_echo] continue=false
534. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [delay_echo] destination_number(7667398) =~ /^\*9195$/ break=on-false
535. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->cf] continue=false
536. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [cf] destination_number(7667398) =~ /^cf$/ break=on-false
537. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->echo] continue=false
538. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [echo] destination_number(7667398) =~ /^\*9196$/ break=on-false
539. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->milliwatt] continue=false
540. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [milliwatt] destination_number(7667398) =~ /^\*9197$/ break=on-false
541. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_zrtp_secure] continue=true
542. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false
543. Dialplan: sofia/external-lan/7398@10.55.4.5 ANTI-Action eval(not_secure)
544. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->is_secure] continue=true
545. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [is_secure] ${sip_via_protocol}(tcp) =~ /tls/ break=on-false
546. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->tone_stream] continue=false
547. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [tone_stream] destination_number(7667398) =~ /^\*9198$/ break=on-false
548. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->hold_music] continue=false
549. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [hold_music] destination_number(7667398) =~ /^\*9664$/ break=on-false
550. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->recordings] continue=false
551. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [recordings] destination_number(7667398) =~ /^\*(732)$/ break=on-false
552. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->directory] continue=false
553. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [directory] destination_number(7667398) =~ /^\*411$/ break=on-false
554. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->wake-up] continue=false
555. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [wake-up] destination_number(7667398) =~ /^\*(925)$/ break=on-false
556. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->valet_park] continue=false
557. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
558. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never
559. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
560. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [valet_park] destination_number(7667398) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=on-false
561. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->operator] continue=false
562. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [operator] destination_number(7667398) =~ /^0$|^operator$/ break=on-false
563. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->operator-forward] continue=false
564. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [operator-forward] destination_number(7667398) =~ /^\*000$/ break=on-false
565. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->do-not-disturb] continue=false
566. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*77$/ break=on-true
567. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*78$|\*363$/ break=on-true
568. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^\*79$/ break=on-true
569. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [do-not-disturb] destination_number(7667398) =~ /^dnd\+7398$/ break=on-true
570. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call-forward] continue=false
571. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*72$/ break=on-true
572. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*73$/ break=on-true
573. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^\*74$/ break=on-true
574. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call-forward] destination_number(7667398) =~ /^forward\+(\Q7398\E)(?:\/(\d+))?$/ break=on-true
575. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call forward all] continue=false
576. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [call forward all] ${user_exists}(true) =~ /true/ break=on-false
577. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call forward all] ${forward_all_enabled}() =~ /true/ break=on-false
578. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->follow-me] continue=false
579. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [follow-me] destination_number(7667398) =~ /^\*21$/ break=on-false
580. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->clear_sip_auto_answer] continue=true
581. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
582. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock date and time] continue=true
583. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock date and time] destination_number(7667398) =~ /^\*9172$/ break=on-false
584. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock time] continue=true
585. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock time] destination_number(7667398) =~ /^\*9170$/ break=on-false
586. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->talking clock date] continue=true
587. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [talking clock date] destination_number(7667398) =~ /^\*9171$/ break=on-false
588. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->call_screen] continue=true
589. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false
590. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->local_extension] continue=true
591. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false
592. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(dialed_extension=${destination_number}) INLINE
593. EXECUTE sofia/external-lan/7398@10.55.4.5 export(dialed_extension=7667398)
594. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[7667398]
595. Dialplan: sofia/external-lan/7398@10.55.4.5 Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination})
596. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(rtp_secure_media=true)
597. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(rtp_secure_media=true)
598. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [local_extension] () =~ // break=on-false
599. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(hangup_after_bridge=true)
600. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(continue_on_fail=true)
601. Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
602. Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
603. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
604. Dialplan: sofia/external-lan/7398@10.55.4.5 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
605. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(api_hangup_hook=lua app.lua hangup)
606. Dialplan: sofia/external-lan/7398@10.55.4.5 Action export(domain_name=${domain_name})
607. Dialplan: sofia/external-lan/7398@10.55.4.5 Action bridge(user/${destination_number}@${domain_name})
608. Dialplan: sofia/external-lan/7398@10.55.4.5 Action lua(app.lua failure_handler)
609. Dialplan: sofia/external-lan/7398@10.55.4.5 parsing [voip.mydomain.com->voicemail] continue=false
610. Dialplan: sofia/external-lan/7398@10.55.4.5 Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false
611. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(record_append=false)
612. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_action=save)
613. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_id=${destination_number})
614. Dialplan: sofia/external-lan/7398@10.55.4.5 Action set(voicemail_profile=default)
615. Dialplan: sofia/external-lan/7398@10.55.4.5 Action lua(app.lua voicemail)
616. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:286 (sofia/external-lan/7398@10.55.4.5) State Change CS_ROUTING -> CS_EXECUTE
617. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/external-lan/7398@10.55.4.5) State ROUTING going to sleep
618. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_EXECUTE (Cur 1 Tot 313)
619. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE
620. 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:209 sofia/external-lan/7398@10.55.4.5 SOFIA EXECUTE
621. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:328 sofia/external-lan/7398@10.55.4.5 Standard EXECUTE
622. EXECUTE sofia/external-lan/7398@10.55.4.5 export(origination_callee_id_name=7667398)
623. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[7667398]
624. EXECUTE sofia/external-lan/7398@10.55.4.5 set(RFC2822_DATE=Wed, 05 Jun 2019 15:33:16 +0100)
625. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [RFC2822_DATE]=[Wed, 05 Jun 2019 15:33:16 +0100]
626. EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial/7398/7667398)
627. EXECUTE sofia/external-lan/7398@10.55.4.5 eval(not_secure)
628. EXECUTE sofia/external-lan/7398@10.55.4.5 limit(hash voip.mydomain.com 7667398  )
629. 2019-06-05 15:33:16.569170 [DEBUG] switch_limit.c:126 incr called: voip.mydomain.com_7667398 max:-1, interval:0
630. 2019-06-05 15:33:16.569170 [DEBUG] mod_hash.c:194 Usage for voip.mydomain.com_7667398 is now 1
631. EXECUTE sofia/external-lan/7398@10.55.4.5 set(rtp_secure_media=true)
632. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [rtp_secure_media]=[true]
633. EXECUTE sofia/external-lan/7398@10.55.4.5 export(rtp_secure_media=true)
634. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [rtp_secure_media]=[true]
635. EXECUTE sofia/external-lan/7398@10.55.4.5 set(hangup_after_bridge=true)
636. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [hangup_after_bridge]=[true]
637. EXECUTE sofia/external-lan/7398@10.55.4.5 set(continue_on_fail=true)
638. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [continue_on_fail]=[true]
639. EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-call_return/7667398/7398)
640. EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial_ext/7667398/6efa6b88-248e-4a15-afca-09df2beb867e)
641. EXECUTE sofia/external-lan/7398@10.55.4.5 set(called_party_call_group=)
642. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [called_party_call_group]=[UNDEF]
643. EXECUTE sofia/external-lan/7398@10.55.4.5 hash(insert/voip.mydomain.com-last_dial//6efa6b88-248e-4a15-afca-09df2beb867e)
644. EXECUTE sofia/external-lan/7398@10.55.4.5 set(api_hangup_hook=lua app.lua hangup)
645. 2019-06-05 15:33:16.569170 [DEBUG] mod_dptools.c:1598 SET sofia/external-lan/7398@10.55.4.5 [api_hangup_hook]=[lua app.lua hangup]
646. EXECUTE sofia/external-lan/7398@10.55.4.5 export(domain_name=voip.mydomain.com)
647. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [domain_name]=[voip.mydomain.com]
648. EXECUTE sofia/external-lan/7398@10.55.4.5 bridge(user/7667398@voip.mydomain.com)
649. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event
650. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event
651. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [dialed_extension]=[7667398] to event
652. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [origination_callee_id_name]=[7667398] to event
653. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [rtp_secure_media]=[true] to event
654. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [domain_name]=[voip.mydomain.com] to event
655. 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
656. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event
657. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [call_direction]=[inbound] to event
658. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [dialed_extension]=[7667398] to event
659. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [origination_callee_id_name]=[7667398] to event
660. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [rtp_secure_media]=[true] to event
661. 2019-06-05 15:33:16.569170 [DEBUG] switch_channel.c:1250 sofia/external-lan/7398@10.55.4.5 EXPORTING[export_vars] [domain_name]=[voip.mydomain.com] to event
662. 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
663. 2019-06-05 15:33:16.569170 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/7667398@185.39.248.196:2658 [ed928a3a-dd04-4402-979f-fafeb5f358be]
664. 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:5019 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_NEW -> CS_INIT
665. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_INIT (Cur 2 Tot 314)
666. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/7667398@185.39.248.196:2658) State INIT
667. 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:93 sofia/internal/7667398@185.39.248.196:2658 SOFIA INIT
668. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw=]
669. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [1 AEAD_AES_256_GCM_8 inline:faMAxHTT6xDoJK8DG73nmIUiV6vOV5VlZoIbT3R78Sheqtqx/wHBkkCyYPo=]
670. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [1 AEAD_AES_256_GCM_8 inline:QrHLk+2xbt+WkyRhJS83PIvqTPYaOVIhxFWkuON5ouNG/9N+M9dZWic9gbI=]
671. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg==]
672. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [2 AEAD_AES_128_GCM_8 inline:4tayk1/aJmWWBCPxKb6uc/oGDK7xoBldZYU9yw==]
673. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [2 AEAD_AES_128_GCM_8 inline:LnAqV/YThGG5+O+aaIYB9eTBv5jbwa+EMqer4w==]
674. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw==]
675. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:azOC6kxeppg9ZO09Qg+mw/7YWCVvx93U3HiKGUqY1ZP2bE/L0IPgmbtAE5gyaQ==]
676. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [3 AES_256_CM_HMAC_SHA1_80 inline:ztZhc1/jJ7zSRK7co49aXvAXdd7A5d4c46Yl9eEDlc++s6mtpZqTvyIEoBKT/g==]
677. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU=]
678. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:S3fooEDZ43IEd93bwM4y/lAKHIFwjgc1Oa8yCl9YrAelsD99uGE=]
679. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [4 AES_192_CM_HMAC_SHA1_80 inline:uaOx/NSQpRl9+UbNiAC3p6N2cYjavh/ai7LCm42DdacMXJH7d7g=]
680. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61]
681. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:2GqvJpVS1GbdKdRWRCxHFrPklrTBXn1N6u8DyA/Q]
682. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:Lk2H537S/4alzeJJM/7olJj7K0XcPBx7GkUmnEvM]
683. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA==]
684. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:yL1fqzga6CRH1TCisIgdgNkrtCkr1IKAOj+NOsGvJA7CWio8vQTnE5Wtx8keHQ==]
685. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [6 AES_256_CM_HMAC_SHA1_32 inline:rhqYIdU+/AtoDOvLtpw6xBnuyoIz2gQc/hppkjM+kPi4F2R5dxlQZK0UlvNUlQ==]
686. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE=]
687. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:GmJdY0oDa1u5KXLocLT38x3ybXHkDDzDFo8HewOk0uZqvR2et6M=]
688. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [7 AES_192_CM_HMAC_SHA1_32 inline:6ueP5qf7Tdj/PLHI0Nb0pTFrMTlT1qj2weBcrLMF/X/t9c9Y3Ss=]
689. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT]
690. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:EbCU7W6c2iU5bDSIGdEaXJJCBbooZVNE6yHAKegu]
691. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:PsTZCAm6QE5Uyp2B8TK5qhmmwGAC9gD89JYRFCxE]
692. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH]
693. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local video crypto Key [9 AES_CM_128_NULL_AUTH inline:WPUvScKp4hkNaGVgmwQZrSoIhsmi88d6KmVYTRu9]
694. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_media.c:1209 Set Local text crypto Key [9 AES_CM_128_NULL_AUTH inline:u2vFsaUv8vSDHNufV+j1Hc374p+Jqyv0cfMY7r8v]
695. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
696. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
697. 2019-06-05 15:33:16.569170 [DEBUG] sofia_glue.c:1271 sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls Setting proxy route to sofia/internal/7667398@185.39.248.196:2658
698. 2019-06-05 15:33:16.569170 [DEBUG] sofia_glue.c:1302 sofia/internal/7667398@185.39.248.196:2658 sending invite version: 1.8.5 -6-31281a0bf1 64bit
699. Local SDP:
700. v=0
701. o=FreeSWITCH 1559728248 1559728249 IN IP4 185.39.250.165
702. s=FreeSWITCH
703. c=IN IP4 185.39.250.165
704. t=0 0
705. m=audio 16948 RTP/SAVP 9 102 103 104 8 0 101 13 105 106
706. a=rtpmap:9 G722/8000
707. a=rtpmap:102 opus/48000/2
708. a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
709. a=rtpmap:103 opus/48000/2
710. a=fmtp:103 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; ptime=20; minptime=10; maxptime=60
711. a=rtpmap:104 opus/48000/2
712. a=fmtp:104 useinbandfec=1; maxaveragebitrate=14000; maxplaybackrate=8000; sprop-maxcapturerate=8000; ptime=20; minptime=10; maxptime=120
713. a=rtpmap:8 PCMA/8000
714. a=rtpmap:0 PCMU/8000
715. a=rtpmap:101 telephone-event/8000
716. a=fmtp:101 0-16
717. a=rtpmap:105 telephone-event/48000
718. a=fmtp:105 0-16
719. a=crypto:1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw=
720. a=crypto:2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg==
721. a=crypto:3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw==
722. a=crypto:4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU=
723. a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61
724. a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA==
725. a=crypto:7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE=
726. a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT
727. a=crypto:9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH
728. a=rtpmap:13 CN/8000
729. a=rtpmap:106 CN/48000
730. a=ptime:20
731. a=sendrecv
732.  
733. nua.c:633 nua_invite() nua: nua_invite: entering
734. nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_invite
735. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
736. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce6c02f9a0) called
737. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
738. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
739. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce600921a0, (nil), 0x7fce6c147ba2, -1) called
740. soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fce600921a0, (nil), 0x7fce6c147ba2, -1) called
741. nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_invite
742. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:40 sofia/internal/7667398@185.39.248.196:2658 Standard INIT
743. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_INIT -> CS_ROUTING
744. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/7667398@185.39.248.196:2658) State INIT going to sleep
745. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce6c02f9a0): adding session usage
746. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fce60050880)
747. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce600921a0) called
748. soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fce600921a0, 0) called
749. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce600921a0, soa_generate_offer): called
750. soa_static.c:1189 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): generating local description
751. soa_static.c:1217 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): upgrade with local description
752. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b73ca70, (nil), ""): called
753. soa_static.c:1446 offer_answer_step() soa_static(0x7fce600921a0, soa_generate_offer): storing local description
754. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce600921a0, [(nil)], [0x7fce6b73ebf8], [0x7fce6b73ebf4]) called
755. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
756. tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658
757. tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658
758. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60061910 993 (993)
759. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce6005b1c0 68 (68)
760. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60074d90 1697 (1697)
761. tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 2758 bytes of 2758 to tls/185.39.248.196:2658
762. tport.c:3496 tport_send_msg() tport_vsend returned 2758
763. send 2758 bytes to tls/[185.39.248.196]:2658 at 15:33:16.418836:
764.    ------------------------------------------------------------------------
765.    INVITE sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls SIP/2.0
766.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKaFrX8FtHvD96Q
767.    Route: <sip:7667398@185.39.248.196:2658>;rinstance=117BFF20;transport=tls
768.    Max-Forwards: 68
769.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
770.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>
771. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_ROUTING (Cur 2 Tot 314)
772.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
773.    CSeq: 5318806 INVITE
774.    Contact: <sip:mod_sofia@185.39.250.165:5061;transport=tls>
775.    User-Agent: FreeSWITCH
776.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
777.    Supported: timer, path, replaces
778.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
779.    Privacy: none
780.    Content-Type: application/sdp
781.    Content-Disposition: session
782.    Content-Length: 1697
783.    X-FS-Support: update_display,send_info
784.    P-Asserted-Identity: "Stephen Barry" <sip:7398@voip.mydomain.com>
785.  
786.    v=0
787.    o=FreeSWITCH 1559728248 1559728249 IN IP4 185.39.250.165
788.    s=FreeSWITCH
789.    c=IN IP4 185.39.250.165
790.    t=0 0
791.    m=audio 16948 RTP/SAVP 9 102 103 104 8 0 101 13 105 106
792.    a=rtpmap:9 G722/8000
793.    a=rtpmap:102 opus/48000/2
794.    a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
795.    a=rtpmap:103 opus/48000/2
796.    a=fmtp:103 useinbandfec=1; maxaveragebitrate=20000; maxplaybackrate=16000; sprop-maxcapturerate=16000; ptime=20; minptime=10; maxptime=60
797.    a=rtpmap:104 opus/48000/2
798.    a=fmtp:104 useinbandfec=1; maxaveragebitrate=14000; maxplaybackrate=8000; sprop-maxcapturerate=8000; ptime=20; minptime=10; maxptime=120
799.    a=rtpmap:8 PCMA/8000
800.    a=rtpmap:0 PCMU/8000
801.    a=rtpmap:101 telephone-event/8000
802.    a=fmtp:101 0-16
803.    a=rtpmap:13 CN/8000
804.    a=rtpmap:105 telephone-event/48000
805.    a=fmtp:105 0-16
806.    a=rtpmap:106 CN/48000
807.    a=crypto:1 AEAD_AES_256_GCM_8 inline:joxzIiOnMXQSer1e+gE4ojRBThpOdCB43dKiLSqImbfVJ/22f1BqVp6LaSw=
808.    a=crypto:2 AEAD_AES_128_GCM_8 inline:B9xOOteDHBIOuFVnpn+EhGDf/p0v4D5wsK0Ofg==
809.    a=crypto:3 AES_256_CM_HMAC_SHA1_80 inline:CRKhSQX3TQb0Yaq2myBlt72OVJWtOgT4eeh3cX56N9xaPaRw6sWCFJzX+7QWkw==
810.    a=crypto:4 AES_192_CM_HMAC_SHA1_80 inline:FHcYFnm81ZxtPNipVZ4h5rWBFmfLKwUC0GBT9j5eX5UHXKhM/AU=
811.    a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:kt/kEwS1HZb3cDc9dO3lMeVMSVNrphk7xDzOjP61
812.    a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:a/N0PngYZ61YZ2qnqlpZiZVjg0kaOIzie+C7x1J/HH6SEbu1h4GtVDB7PML9pA==
813.    a=crypto:7 AES_192_CM_HMAC_SHA1_32 inline:t2ajot1NVJWiHu7bKwirL9wCY6IXrwD/5GR+pP/VeI8+6dhkSbE=
814.    a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:+mmPBRkPSQd95WZQh8yADqwPO7tUlwEvy6NV+wcT
815.    a=crypto:9 AES_CM_128_NULL_AUTH inline:uxnfyhaXMQp1ZYtMc6XSG3EMsTw7xXKCrbTr5YNH
816.    a=ptime:20
817.    ------------------------------------------------------------------------
818. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
819. nta.c:8310 outgoing_send() nta: sent INVITE (5318806) to tls/185.39.248.196:2658
820. tport.c:4164 tport_pend() tport_pend(0x7fce6007ac40): pending 0x7fce6008f8c0 for tls/185.39.248.196:2658 (already 0)
821. nta.c:1350 set_timeout() nta: timer set to 32000 ms
822. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: init -> calling, sent offer
823. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce600921a0, [0x7fce6b73ebd8], [0x7fce6b73ebe0], [(nil)]) called
824. nua_stack.c:269 nua_stack_event() nua(0x7fce6c02f9a0): event i_state INVITE sent
825. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/7667398@185.39.248.196:2658) State ROUTING
826. 2019-06-05 15:33:16.569170 [DEBUG] mod_sofia.c:154 sofia/internal/7667398@185.39.248.196:2658 SOFIA ROUTING
827. 2019-06-05 15:33:16.569170 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_ROUTING -> CS_CONSUME_MEDIA
828. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/7667398@185.39.248.196:2658) State ROUTING going to sleep
829. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
830. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 314)
831. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
832. 2019-06-05 15:33:16.569170 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [calling][0]
833. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
834. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/7667398@185.39.248.196:2658) State CONSUME_MEDIA
835. 2019-06-05 15:33:16.569170 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/7667398@185.39.248.196:2658) State CONSUME_MEDIA going to sleep
836. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
837. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
838. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 421
839. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 421 bytes, veclen = 1
840. recv 421 bytes from tls/[185.39.248.196]:2658 at 15:33:16.593739:
841.    ------------------------------------------------------------------------
842.    SIP/2.0 100 Trying
843.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165
844.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
845.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
846.    CSeq: 5318806 INVITE
847.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>
848.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a)
849.    Content-Length: 0
850.  
851.    ------------------------------------------------------------------------
852. tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60036740 (421 bytes) from tls/185.39.248.196:2658/sips next=(nil)
853. nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (5318806)
854. nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction
855. nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 174.962 ms
856. tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60036740 (preliminary)
857. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
858. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
859. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
860. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 607
861. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60036740 from (tls/185.39.248.196:2658) has 607 bytes, veclen = 1
862. recv 607 bytes from tls/[185.39.248.196]:2658 at 15:33:16.663273:
863.    ------------------------------------------------------------------------
864.    SIP/2.0 180 Ringing
865.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165
866.    Contact: <sip:7667398@185.39.248.196:2658;transport=tls>
867.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
868.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
869.    CSeq: 5318806 INVITE
870.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
871.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
872.    Supported: replaces, path
873.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a)
874.    Content-Length: 0
875.  
876.    ------------------------------------------------------------------------
877. tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60036740 (607 bytes) from tls/185.39.248.196:2658/sips next=(nil)
878. nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (5318806)
879. nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction
880. tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60036740 (preliminary)
881. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_invite 180 Ringing
882. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: calling -> proceeding
883. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 180 Ringing
884. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
885. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
886. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
887. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
888. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
889. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
890. 2019-06-05 15:33:16.809164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [proceeding][180]
891. 2019-06-05 15:33:16.809164 [NOTICE] sofia.c:7401 Ring-Ready sofia/internal/7667398@185.39.248.196:2658!
892. 2019-06-05 15:33:16.809164 [DEBUG] switch_channel.c:3354 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change DOWN -> RINGING
893. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
894. 2019-06-05 15:33:16.829170 [INFO] switch_ivr_originate.c:1246 Sending early media
895. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/external-lan/7398@10.55.4.5] 10.55.4.7 port 26324 -> 10.55.102.51 port 16670 codec: 9 ms: 20
896. 2019-06-05 15:33:16.829170 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms
897. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8815 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101
898. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8822 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf receive payload to 101
899. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_media.c:8845 sofia/external-lan/7398@10.55.4.5 Set rtp dtmf delay to 40
900. 2019-06-05 15:33:16.829170 [DEBUG] mod_sofia.c:2505 Ring SDP:
901. v=0
902. o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7
903. s=FreeSWITCH
904. c=IN IP4 10.55.4.7
905. t=0 0
906. m=audio 26324 RTP/AVP 9
907. a=rtpmap:9 G722/8000
908. a=ptime:20
909. a=sendrecv
910.  
911. 2019-06-05 15:33:16.829170 [NOTICE] mod_sofia.c:2508 Pre-Answer sofia/external-lan/7398@10.55.4.5!
912. 2019-06-05 15:33:16.829170 [DEBUG] switch_channel.c:3482 (sofia/external-lan/7398@10.55.4.5) Callstate Change RINGING -> EARLY
913. nua.c:879 nua_respond() nua: nua_respond: entering
914. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
915. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 183 Session Progress
916. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
917. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
918. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce70015cfd, -1) called
919. 2019-06-05 15:33:16.829170 [DEBUG] switch_ivr_originate.c:1304 Raw Codec Activation Success L16@16000hz 1 channel 20ms
920. 2019-06-05 15:33:16.829170 [DEBUG] switch_core_codec.c:223 sofia/external-lan/7398@10.55.4.5 Push codec L16:100
921. soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fce74014690, (nil), 0x7fce70015cfd, -1) called
922. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
923. soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7fce74014690) called
924. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce74014690, soa_generate_answer): called
925. soa_static.c:1189 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): generating local description
926. soa_static.c:1230 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): upgrade with remote description
927. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b5e8ab0, 0x7fce74015680, ""): called
928. soa_static.c:1446 offer_answer_step() soa_static(0x7fce74014690, soa_generate_answer): storing local description
929. 2019-06-05 15:33:16.829170 [DEBUG] switch_ivr_originate.c:1373 Play Ringback Tone [%(2000,4000,440,480)]
930. soa.c:1730 soa_activate() soa_activate(static::0x7fce74014690, (nil)) called
931. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called
932. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
933. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 889 bytes of 889 to tcp/10.55.4.5:55848
934. tport.c:3496 tport_send_msg() tport_vsend returned 889
935. send 889 bytes to tcp/[10.55.4.5]:55848 at 15:33:16.682014:
936.    ------------------------------------------------------------------------
937.    SIP/2.0 183 Session Progress
938.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848
939.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
940.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
941.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
942.    CSeq: 101 INVITE
943.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
944.    User-Agent: FreeSWITCH
945.    Accept: application/sdp
946.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
947.    Supported: timer, path, replaces
948.    Allow-Events: talk, hold, conference, refer
949.    Content-Type: application/sdp
950.    Content-Disposition: session
951.    Content-Length: 158
952.    P-Asserted-Identity: "7667398" <sip:7667398@10.55.4.7>
953.  
954.    v=0
955.    o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7
956.    s=FreeSWITCH
957.    c=IN IP4 10.55.4.7
958.    t=0 0
959.    m=audio 26324 RTP/AVP 9
960.    a=rtpmap:9 G722/8000
961.    a=ptime:20
962.    ------------------------------------------------------------------------
963. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
964. nta.c:6797 incoming_reply() nta: sent 183 Session Progress for INVITE (101)
965. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: received -> early, sent answer
966. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called
967. soa.c:616 soa_get_params() soa_get_params(static::0x7fce74014690, ...) called
968. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 183 Session Progress
969. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
970. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
971. 2019-06-05 15:33:16.849171 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [early][183]
972. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
973. 2019-06-05 15:33:16.949164 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
974. nta.c:1296 agent_timer() nta: timer set next to 58323 ms
975. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
976. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
977. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 1017
978. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60078270 from (tls/185.39.248.196:2658) has 1017 bytes, veclen = 1
979. recv 1017 bytes from tls/[185.39.248.196]:2658 at 15:33:21.582934:
980.    ------------------------------------------------------------------------
981.    SIP/2.0 200 OK
982.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKaFrX8FtHvD96Q;received=185.39.250.165
983.    Contact: <sip:7667398@185.39.248.196:2658;transport=tls>
984.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
985.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
986.    CSeq: 5318806 INVITE
987.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
988.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
989.    Supported: replaces, path
990.    Content-Type: application/sdp
991.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a)
992.    Content-Length: 382
993.  
994.    v=0
995.    o=- 2214276607 13634 IN IP4 172.26.170.170
996.    s=qdusifw
997.    c=IN IP4 10.71.172.74
998.    t=0 0
999.    m=audio 23288 RTP/SAVP 102 101
1000.    a=rtpmap:101 telephone-event/8000
1001.    a=rtpmap:102 opus/48000/2
1002.    a=fmtp:101 0-15
1003.    a=fmtp:102 maxplaybackrate=16000;maxaveragebitrate=30000;useinbandfec=1
1004.    a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D
1005.    a=ptime:20
1006.    a=sendrecv
1007.    ------------------------------------------------------------------------
1008. tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60078270 (1017 bytes) from tls/185.39.248.196:2658/sips next=(nil)
1009. nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (5318806)
1010. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
1011. tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6008f8c0 by 0x7fce600336a0 with 0x7fce60078270
1012. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce600921a0, (nil), 0x7fce60060d2b, 382) called
1013. soa.c:1595 soa_process_answer() soa_process_answer(static::0x7fce600921a0) called
1014. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce600921a0, soa_process_answer): called
1015. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6005fff0, 0x7fce6007cb80, ""): called
1016. soa_static.c:1304 offer_answer_step() soa_static(0x7fce600921a0, soa_process_answer): upgrade codecs with remote description
1017. soa_static.c:1446 offer_answer_step() soa_static(0x7fce600921a0, soa_process_answer): storing local description
1018. soa.c:1730 soa_activate() soa_activate(static::0x7fce600921a0, (nil)) called
1019. nua_session.c:988 nua_session_client_response() nua(0x7fce6c02f9a0): INVITE: processed SDP answer in 200 OK
1020. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_invite 200 OK
1021. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: proceeding -> completing, received answer
1022. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce600921a0, [0x7fce6b73e5e8], [0x7fce6b73e5f0], [(nil)]) called
1023. soa.c:616 soa_get_params() soa_get_params(static::0x7fce600921a0, ...) called
1024. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 OK
1025. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1026. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
1027. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1028. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1029. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1030. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1031. 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [completing][200]
1032. 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7301 Remote SDP:
1033. v=0
1034. o=- 2214276607 13634 IN IP4 172.26.170.170
1035. s=qdusifw
1036. c=IN IP4 10.71.172.74
1037. t=0 0
1038. m=audio 23288 RTP/SAVP 102 101
1039. a=rtpmap:102 opus/48000/2
1040. a=fmtp:102 maxplaybackrate=16000;maxaveragebitrate=30000;useinbandfec=1
1041. a=rtpmap:101 telephone-event/8000
1042. a=fmtp:101 0-15
1043. a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D
1044. a=ptime:20
1045.  
1046. 2019-06-05 15:33:21.729164 [NOTICE] sofia.c:7304 Pre-Answer sofia/internal/7667398@185.39.248.196:2658!
1047. 2019-06-05 15:33:21.729164 [DEBUG] switch_channel.c:3482 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change RINGING -> EARLY
1048. nua.c:639 nua_ack() nua: nua_ack: entering
1049. nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_ack
1050. nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_ack
1051. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1052. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1053. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
1054. soa.c:1730 soa_activate() soa_activate(static::0x7fce600921a0, (nil)) called
1055. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
1056. tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658
1057. tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658
1058. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce60052100 474 (474)
1059. tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 474 bytes of 474 to tls/185.39.248.196:2658
1060. tport.c:3496 tport_send_msg() tport_vsend returned 474
1061. send 474 bytes to tls/[185.39.248.196]:2658 at 15:33:21.584434:
1062.    ------------------------------------------------------------------------
1063.    ACK sip:7667398@185.39.248.196:2658;transport=tls SIP/2.0
1064.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKBrHpaBBNSpZSK
1065.    Max-Forwards: 70
1066.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
1067.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
1068.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
1069.    CSeq: 5318806 ACK
1070.    Contact: <sip:mod_sofia@185.39.250.165:5061;transport=tls>
1071.    Content-Length: 0
1072.  
1073.    ------------------------------------------------------------------------
1074. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
1075. nta.c:8310 outgoing_send() nta: sent ACK (5318806) to tls/185.39.248.196:2658
1076. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: completing -> ready
1077. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 ACK sent
1078. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_active 200 Call active
1079. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1080. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1081. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1082. 2019-06-05 15:33:21.729164 [DEBUG] sofia.c:7291 Channel sofia/internal/7667398@185.39.248.196:2658 entering state [ready][200]
1083. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
1084. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
1085. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
1086. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
1087. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
1088. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1813 Found suite AES_CM_128_HMAC_SHA1_80
1089. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:1883 Set Remote Key [5 AES_CM_128_HMAC_SHA1_80 inline:9Opg2xJ45rrk44VJptkFTd3D3cQjIZWBDnF+o20D]
1090. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[G722:9:8000:20:64000:1]
1091. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
1092. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
1093. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
1094. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
1095. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1]
1096. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
1097. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
1098. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
1099. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
1100. 2019-06-05 15:33:21.729164 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps]
1101. 2019-06-05 15:33:21.729164 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps]
1102. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/7667398@185.39.248.196:2658 opus/8000 20 ms 960 samples 0 bits 1 channels
1103. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_codec.c:111 sofia/internal/7667398@185.39.248.196:2658 Original read codec set to opus:116
1104. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:5795 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf send payload to 101 recv payload to 101
1105. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/7667398@185.39.248.196:2658] 10.66.4.7 port 16948 -> 10.71.172.74 port 23288 codec: 102 ms: 20
1106. 2019-06-05 15:33:21.729164 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 960 bytes per 20ms
1107. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8815 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf send payload to 101
1108. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8822 sofia/internal/7667398@185.39.248.196:2658 Set 2833 dtmf receive payload to 101
1109. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_media.c:8845 sofia/internal/7667398@185.39.248.196:2658 Set rtp dtmf delay to 40
1110. 2019-06-05 15:33:21.729164 [INFO] switch_rtp.c:4104 Activating audio Secure RTP SEND
1111. 2019-06-05 15:33:21.729164 [INFO] switch_rtp.c:4082 Activating audio Secure RTP RECV
1112. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
1113. 2019-06-05 15:33:21.729164 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
1114. 2019-06-05 15:33:21.729164 [NOTICE] sofia.c:8429 Channel [sofia/internal/7667398@185.39.248.196:2658] has been answered
1115. 2019-06-05 15:33:21.729164 [DEBUG] switch_channel.c:3781 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change EARLY -> ACTIVE
1116. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1117. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1118. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1119. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_codec.c:248 sofia/external-lan/7398@10.55.4.5 Restore previous codec G722:9.
1120. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/external-lan/7398@10.55.4.5.
1121. 2019-06-05 15:33:21.749169 [DEBUG] mod_sofia.c:882 Local SDP sofia/external-lan/7398@10.55.4.5:
1122. v=0
1123. o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
1124. s=FreeSWITCH
1125. c=IN IP4 10.55.4.7
1126. t=0 0
1127. m=audio 26324 RTP/AVP 9
1128. a=rtpmap:9 G722/8000
1129. a=ptime:20
1130. a=sendrecv
1131.  
1132. nua.c:879 nua_respond() nua: nua_respond: entering
1133. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK
1134. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1135. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
1136. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
1137. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce700443d3, -1) called
1138. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
1139. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called
1140. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
1141. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 903 bytes of 903 to tcp/10.55.4.5:55848
1142. tport.c:3496 tport_send_msg() tport_vsend returned 903
1143. send 903 bytes to tcp/[10.55.4.5]:55848 at 15:33:21.600438:
1144.    ------------------------------------------------------------------------
1145.    SIP/2.0 200 OK
1146.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60c3af46a1f;rport=55848
1147.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1148.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1149.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1150.    CSeq: 101 INVITE
1151.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
1152.    User-Agent: FreeSWITCH
1153.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
1154.    Require: timer
1155.    Supported: timer, path, replaces
1156.    Allow-Events: talk, hold, conference, refer
1157.    Session-Expires: 1800;refresher=uac
1158.    Content-Type: application/sdp
1159.    Content-Disposition: session
1160.    Content-Length: 158
1161.    P-Asserted-Identity: "7667398" <sip:7667398@10.55.4.7>
1162.  
1163.    v=0
1164.    o=FreeSWITCH 1559718872 1559718873 IN IP4 10.55.4.7
1165.    s=FreeSWITCH
1166.    c=IN IP4 10.55.4.7
1167.    t=0 0
1168.    m=audio 26324 RTP/AVP 9
1169.    a=rtpmap:9 G722/8000
1170.    a=ptime:20
1171.    ------------------------------------------------------------------------
1172. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1173. nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (101)
1174. nta.c:1348 set_timeout() nta: timer shortened to 500 ms
1175. 2019-06-05 15:33:21.749169 [NOTICE] switch_ivr_originate.c:3740 Channel [sofia/external-lan/7398@10.55.4.5] has been answered
1176. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: early -> completed, sent answer
1177. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called
1178. soa.c:616 soa_get_params() soa_get_params(static::0x7fce74014690, ...) called
1179. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK
1180. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1181. 2019-06-05 15:33:21.749169 [DEBUG] switch_channel.c:3781 (sofia/external-lan/7398@10.55.4.5) Callstate Change EARLY -> ACTIVE
1182. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1183. 2019-06-05 15:33:21.749169 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [completed][200]
1184. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1185. 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/internal/7667398@185.39.248.196:2658]
1186. 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/internal/7667398@185.39.248.196:2658]
1187. 2019-06-05 15:33:21.749169 [DEBUG] switch_ivr_bridge.c:1782 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
1188. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 314)
1189. 2019-06-05 15:33:21.749169 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/7667398@185.39.248.196:2658) State EXCHANGE_MEDIA
1190. 2019-06-05 15:33:21.749169 [DEBUG] mod_sofia.c:646 SOFIA EXCHANGE_MEDIA
1191. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
1192. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
1193. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74013db0 from (tcp/10.55.4.5:55848) has 463 bytes, veclen = 1
1194. recv 463 bytes from tcp/[10.55.4.5]:55848 at 15:33:21.602290:
1195.    ------------------------------------------------------------------------
1196.    ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
1197.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60d6ac3319b
1198.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1199.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1200.    Date: Wed, 05 Jun 2019 14:33:16 GMT
1201.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1202.    User-Agent: Cisco-CUCM10.5
1203.    Max-Forwards: 70
1204.    CSeq: 101 ACK
1205.    Allow-Events: presence, kpml
1206.    Content-Length: 0
1207.  
1208.    ------------------------------------------------------------------------
1209. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74013db0 (463 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
1210. nta.c:2880 agent_recv_request() nta: received ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 101)
1211. nta.c:3019 agent_recv_request() nta: ACK (101) is going to INVITE (101)
1212. nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering
1213. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fce74014690) called
1214. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_ack 200 OK
1215. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: completed -> ready
1216. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK
1217. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_active 200 Call active
1218. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1219. nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768])
1220. nta.c:5744 incoming_free() nta: incoming_free(0x7fce74003c30)
1221. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1222. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1223. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1224. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1225. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1226. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1227. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1228. 2019-06-05 15:33:21.749169 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [ready][200]
1229. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1230. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1231. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1232. 2019-06-05 15:33:21.789165 [NOTICE] switch_core_media.c:15578 Activating write resampler
1233. 2019-06-05 15:33:21.809171 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
1234. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
1235. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
1236. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps]
1237. 2019-06-05 15:33:21.809171 [NOTICE] switch_core_media.c:15578 Activating write resampler
1238. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[1] PLC[0] FEC[0]
1239. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
1240. 2019-06-05 15:33:21.809171 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [32000bps]
1241. 2019-06-05 15:33:22.009176 [INFO] switch_rtp.c:7510 Auto Changing audio port from 10.71.172.74:23288 to 185.39.248.196:23288
1242. nta.c:1289 agent_timer() nta: timer not set
1243. freeswitch@fpbx01>
1244. freeswitch@fpbx01>
1245. freeswitch@fpbx01>
1246. freeswitch@fpbx01>
1247. freeswitch@fpbx01>
1248. freeswitch@fpbx01>
1249. freeswitch@fpbx01>
1250. freeswitch@fpbx01>
1251. freeswitch@fpbx01>
1252. freeswitch@fpbx01>
1253. freeswitch@fpbx01>
1254. freeswitch@fpbx01>
1255. freeswitch@fpbx01>
1256. tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fce600466b0): events IN
1257. tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7fce600466b0): new secondary tport 0x7fce60053a50
1258. tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7fce60053a50): Setting TCP_KEEPIDLE to 30
1259. tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7fce60053a50): Setting TCP_KEEPINTVL to 30
1260. tport_type_tls.c:610 tport_tls_accept() tport_tls_accept(0x7fce60053a50): new connection from tls/162.243.35.55:64178/sips
1261. tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING
1262. freeswitch@fpbx01>
1263. tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING
1264. tport_tls.c:960 tls_connect() tls_connect(0x7fce60053a50): events NEGOTIATING
1265. tport_tls.c:603 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (name): ECDHE-RSA-AES256-SHA
1266. tport_tls.c:605 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (version): TLSv1/SSLv3
1267. tport_tls.c:608 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (bits/alg_bits): 256/256
1268. tport_tls.c:611 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): TLS cipher chosen (description): ECDHE-RSA-AES256-SHA    SSLv3 Kx=ECDH     Au=RSA  Enc=AES(256)  Mac=SHA1
1269.  
1270. tport_tls.c:616 tls_post_connection_check() tls_post_connection_check(0x7fce60053a50): Peer did not provide X.509 Certificate.
1271. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
1272. freeswitch@fpbx01>
1273. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN
1274. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60053a50)
1275. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60053a50): tls_read() returned 542
1276. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60053a50) msg 0x7fce600aefb0 from (tls/162.243.35.55:64178) has 542 bytes, veclen = 1
1277. recv 542 bytes from tls/[162.243.35.55]:64178 at 15:33:27.091213:
1278.    ------------------------------------------------------------------------
1279.    REGISTER sip:voip.mydomain.com SIP/2.0
1280.    Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bKDTnvBCgWYgCf4htH;rport
1281.    Contact: <sip:766@162.243.35.55:64178;rinstance=FB4BBA12;transport=tls>;expires=600
1282.    Max-Forwards: 70
1283.    From: <sip:766@voip.mydomain.com>;tag=0379E1A1DB270E77E864F1CC563F5582
1284.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
1285.    Supported: replaces, path
1286.    To: <sip:766@voip.mydomain.com>
1287.    Expires: 600
1288.    Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A
1289.    CSeq: 3 REGISTER
1290.    User-Agent: Acrobits SIPIS
1291.    Content-Length: 0
1292.  
1293.    ------------------------------------------------------------------------
1294. tport.c:3027 tport_deliver() tport_deliver(0x7fce60053a50): msg 0x7fce600aefb0 (542 bytes) from tls/162.243.35.55:64178/sips next=(nil)
1295. nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 3)
1296. nta.c:3085 agent_recv_request() nta: REGISTER (3) going to a default leg
1297. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
1298. nua_stack.c:899 nh_create() nua: nh_create: entering
1299. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
1300. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1301. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce600ae8c0) called
1302. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083780, ...) called
1303. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce600ae8c0): adding registrar usage
1304. tport.c:4164 tport_pend() tport_pend(0x7fce60053a50): pending (nil) for tls/162.243.35.55:64178 (already 0)
1305. nua_stack.c:271 nua_stack_event() nua(0x7fce600ae8c0): event i_register 100 Trying
1306. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
1307. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1308. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1309. nua.c:879 nua_respond() nua: nua_respond: entering
1310. nua_stack.c:529 nua_signal() nua(0x7fce600ae8c0): sent signal r_respond
1311. nua_stack.c:573 nua_stack_signal() nua(0x7fce600ae8c0): recv signal r_respond 401 Unauthorized
1312. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1313. 2019-06-05 15:33:27.249166 [WARNING] sofia_reg.c:1798 SIP auth challenge (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 162.243.35.55
1314. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083780, ...) called
1315. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1316. nua_stack.c:529 nua_signal() nua(0x7fce600ae8c0): sent signal r_destroy
1317. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1318. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1319. tport.c:3261 tport_tsend() tport_tsend(0x7fce60053a50) tpn = TLS/162.243.35.55:64178
1320. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b08b0 107 (107)
1321. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600af679 71 (71)
1322. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b091b 50 (50)
1323. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600af748 69 (69)
1324. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b094d 313 (313)
1325. tport.c:3598 tport_vsend() tport_vsend(0x7fce60053a50): 610 bytes of 610 to tls/162.243.35.55:64178
1326. tport.c:3496 tport_send_msg() tport_vsend returned 610
1327. send 610 bytes to tls/[162.243.35.55]:64178 at 15:33:27.091551:
1328.    ------------------------------------------------------------------------
1329.    SIP/2.0 401 Unauthorized
1330.    Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bKDTnvBCgWYgCf4htH;rport=64178
1331.    From: <sip:766@voip.mydomain.com>;tag=0379E1A1DB270E77E864F1CC563F5582
1332.    To: <sip:766@voip.mydomain.com>;tag=Q41HF6rHrt81S
1333.    Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A
1334.    CSeq: 3 REGISTER
1335.    User-Agent: FreeSWITCH
1336.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1337.    Supported: timer, path, replaces
1338.    WWW-Authenticate: Digest realm="voip.mydomain.com", nonce="33412b5e-8a70-4ccf-99e4-385b0439701d", algorithm=MD5, qop="auth"
1339.    Content-Length: 0
1340.  
1341.    ------------------------------------------------------------------------
1342. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
1343. nta.c:6797 incoming_reply() nta: sent 401 Unauthorized for REGISTER (3)
1344. nta.c:5744 incoming_free() nta: incoming_free(0x7fce600af360)
1345. nua_stack.c:569 nua_stack_signal() nua(0x7fce600ae8c0): recv signal r_destroy
1346. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce600ae8c0): removing registrar usage
1347. tport.c:4226 tport_release() tport_release(0x7fce60053a50): (nil) by 0x7fce600ae8c0 with (nil)
1348. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
1349. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
1350. soa.c:356 soa_destroy() soa_destroy(static::0x7fce60083780) called
1351. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN
1352. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60053a50)
1353. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60053a50): tls_read() returned 790
1354. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60053a50) msg 0x7fce600ae4a0 from (tls/162.243.35.55:64178) has 790 bytes, veclen = 1
1355. recv 790 bytes from tls/[162.243.35.55]:64178 at 15:33:27.163818:
1356.    ------------------------------------------------------------------------
1357.    REGISTER sip:voip.mydomain.com SIP/2.0
1358.    Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bK7VZrGlJs0ipKKRkF;rport
1359.    Contact: <sip:766@162.243.35.55:64178;rinstance=FB4BBA12;transport=tls>;expires=600
1360.    Max-Forwards: 70
1361.    From: <sip:766@voip.mydomain.com>;tag=0379E1A1DB270E77E864F1CC563F5582
1362.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
1363.    Supported: replaces, path
1364.    To: <sip:766@voip.mydomain.com>
1365.    Expires: 600
1366.    Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A
1367.    CSeq: 4 REGISTER
1368.    Authorization: Digest username="766",realm="voip.mydomain.com",algorithm=MD5,uri="sip:voip.mydomain.com",nonce="33412b5e-8a70-4ccf-99e4-385b0439701d",qop=auth,cnonce="XPfSt9oi6WwqwF0s3uKNQX1I",nc=00000001,response="17317ab4aecbbf1ebd439a089ca22355"
1369.    User-Agent: Acrobits SIPIS
1370.    Content-Length: 0
1371.  
1372.    ------------------------------------------------------------------------
1373. tport.c:3027 tport_deliver() tport_deliver(0x7fce60053a50): msg 0x7fce600ae4a0 (790 bytes) from tls/162.243.35.55:64178/sips next=(nil)
1374. nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 4)
1375. nta.c:3085 agent_recv_request() nta: REGISTER (4) going to a default leg
1376. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
1377. nua_stack.c:899 nh_create() nua: nh_create: entering
1378. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
1379. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1380. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce600832c0) called
1381. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083700, ...) called
1382. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce600832c0): adding registrar usage
1383. tport.c:4164 tport_pend() tport_pend(0x7fce60053a50): pending (nil) for tls/162.243.35.55:64178 (already 0)
1384. nua_stack.c:271 nua_stack_event() nua(0x7fce600832c0): event i_register 100 Trying
1385. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
1386. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1387. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1388. 2019-06-05 15:33:27.309167 [WARNING] sofia_reg.c:2935 Can't find user [766@voip.mydomain.com] from 162.243.35.55
1389. You must define a domain called 'voip.mydomain.com' in your directory and add a user with the id="766" attribute
1390. and you must configure your device to use the proper domain in it's authentication credentials.
1391. nua.c:879 nua_respond() nua: nua_respond: entering
1392. nua_stack.c:573 nua_stack_signal() nua(0x7fce600832c0): recv signal r_respond 403 Forbidden
1393. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1394. soa.c:403 soa_set_params() soa_set_params(static::0x7fce60083700, ...) called
1395. nua_stack.c:529 nua_signal() nua(0x7fce600832c0): sent signal r_respond
1396. 2019-06-05 15:33:27.309167 [WARNING] sofia_reg.c:1743 SIP auth failure (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 162.243.35.55
1397. tport.c:3261 tport_tsend() tport_tsend(0x7fce60053a50) tpn = TLS/162.243.35.55:64178
1398. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1399. nua_stack.c:529 nua_signal() nua(0x7fce600832c0): sent signal r_destroy
1400. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1401. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1402. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0b20 104 (104)
1403. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600ad929 71 (71)
1404. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0b88 50 (50)
1405. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600ad9f8 69 (69)
1406. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce600c1900 0x7fce600b0bba 189 (189)
1407. tport.c:3598 tport_vsend() tport_vsend(0x7fce60053a50): 483 bytes of 483 to tls/162.243.35.55:64178
1408. tport.c:3496 tport_send_msg() tport_vsend returned 483
1409. send 483 bytes to tls/[162.243.35.55]:64178 at 15:33:27.167172:
1410.    ------------------------------------------------------------------------
1411.    SIP/2.0 403 Forbidden
1412.    Via: SIP/2.0/TLS 162.243.35.55:64178;branch=z9hG4bK7VZrGlJs0ipKKRkF;rport=64178
1413.    From: <sip:766@voip.mydomain.com>;tag=0379E1A1DB270E77E864F1CC563F5582
1414.    To: <sip:766@voip.mydomain.com>;tag=rDUaH19mN3ymN
1415.    Call-ID: 2D3450B0F4D400EB567B897821A37D9F82A0EA3A
1416.    CSeq: 4 REGISTER
1417.    User-Agent: FreeSWITCH
1418.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1419.    Supported: timer, path, replaces
1420.    Content-Length: 0
1421.  
1422.    ------------------------------------------------------------------------
1423. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
1424. nta.c:6797 incoming_reply() nta: sent 403 Forbidden for REGISTER (4)
1425. nta.c:5744 incoming_free() nta: incoming_free(0x7fce600afd50)
1426. nua_stack.c:569 nua_stack_signal() nua(0x7fce600832c0): recv signal r_destroy
1427. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce600832c0): removing registrar usage
1428. tport.c:4226 tport_release() tport_release(0x7fce60053a50): (nil) by 0x7fce600832c0 with (nil)
1429. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60053a50): reset timer
1430. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
1431. soa.c:356 soa_destroy() soa_destroy(static::0x7fce60083700) called
1432. freeswitch@fpbx01>
1433. freeswitch@fpbx01>
1434. freeswitch@fpbx01>
1435. freeswitch@fpbx01>
1436. freeswitch@fpbx01>
1437. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
1438. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
1439. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74008dc0 from (tcp/10.55.4.5:55848) has 1413 bytes, veclen = 1
1440. recv 1413 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.019210:
1441.    ------------------------------------------------------------------------
1442.    INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
1443.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f
1444.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1445.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1446.    Date: Wed, 05 Jun 2019 14:33:30 GMT
1447.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1448.    Supported: timer,resource-priority,replaces
1449.    User-Agent: Cisco-CUCM10.5
1450.   Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
1451.    CSeq: 102 INVITE
1452.    Max-Forwards: 70
1453.    Expires: 180
1454.    Allow-Events: presence
1455.    Call-Info: <urn:x-cisco-remotecc:callinfo>;x-cisco-video-traffic-class=VIDEO_UNSPECIFIED
1456.    Supported: X-cisco-srtp-fallback
1457.    Supported: Geolocation
1458.    Session-Expires:  1800;refresher=uac
1459.    Min-SE:  1800
1460.    P-Asserted-Identity: "Stephen Barry" <sip:7398@10.55.4.5>
1461.    Remote-Party-ID: "Stephen Barry" <sip:7398@10.55.4.5>;party=calling;screen=yes;privacy=off
1462.    Contact: <sip:7398@10.55.4.5:5060;transport=tcp>
1463.    Content-Type: application/sdp
1464.    Content-Length: 367
1465.  
1466.    v=0
1467.    o=CiscoSystemsCCM-SIP 3080835 2 IN IP4 10.55.4.5
1468.    s=SIP Call
1469.    c=IN IP4 0.0.0.0
1470.    b=TIAS:64000
1471.    b=AS:64
1472.    t=0 0
1473.    m=audio 16670 RTP/AVP 9 8 0 116 18 101
1474.    a=rtpmap:9 G722/8000
1475.    a=rtpmap:8 PCMA/8000
1476.    a=rtpmap:0 PCMU/8000
1477.    a=rtpmap:116 iLBC/8000
1478.    a=maxptime:60
1479.    a=fmtp:116 mode=20
1480.    a=rtpmap:18 G729/8000
1481.    a=inactive
1482.    a=rtpmap:101 telephone-event/8000
1483.    a=fmtp:101 0-15
1484.    ------------------------------------------------------------------------
1485. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74008dc0 (1413 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
1486. nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 102)
1487. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
1488. nta.c:3060 agent_recv_request() nta: INVITE (102) going to existing leg
1489. nta.c:1350 set_timeout() nta: timer set to 2000 ms
1490. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
1491. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called
1492. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fce74014690, (nil), 0x7fce74003a36, 367) called
1493. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying
1494. nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: received received offer
1495. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fce74014690, [0x7fce6b5ea8d8], [0x7fce6b5ea8e0], [(nil)]) called
1496. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying
1497. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1498. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1499. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1500. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1501. nua.c:879 nua_respond() nua: nua_respond: entering
1502. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
1503. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 100 Trying
1504. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1505. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
1506. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
1507. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 355 bytes of 355 to tcp/10.55.4.5:55848
1508. tport.c:3496 tport_send_msg() tport_vsend returned 355
1509. send 355 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.020262:
1510.    ------------------------------------------------------------------------
1511.    SIP/2.0 100 Trying
1512.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f;rport=55848
1513.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1514.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1515.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1516.    CSeq: 102 INVITE
1517.    User-Agent: FreeSWITCH
1518.    Content-Length: 0
1519.  
1520.    ------------------------------------------------------------------------
1521. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1522. nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (102)
1523. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1524. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1525. 2019-06-05 15:33:30.169172 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100]
1526. 2019-06-05 15:33:30.169172 [DEBUG] sofia.c:7301 Remote SDP:
1527. v=0
1528. o=CiscoSystemsCCM-SIP 3080835 2 IN IP4 10.55.4.5
1529. s=SIP Call
1530. c=IN IP4 0.0.0.0
1531. b=TIAS:64000
1532. b=AS:64
1533. t=0 0
1534. m=audio 16670 RTP/AVP 9 8 0 116 18 101
1535. a=rtpmap:9 G722/8000
1536. a=rtpmap:8 PCMA/8000
1537. a=rtpmap:0 PCMU/8000
1538. a=rtpmap:116 iLBC/8000
1539. a=fmtp:116 mode=20
1540. a=rtpmap:18 G729/8000
1541. a=rtpmap:101 telephone-event/8000
1542. a=fmtp:101 0-15
1543. a=inactive
1544. a=maxptime:60
1545.  
1546. 2019-06-05 15:33:30.169172 [WARNING] switch_core_media.c:4877 RFC2543 from March 1999 called; They want their 0.0.0.0 hold method back.....
1547. 2019-06-05 15:33:30.169172 [DEBUG] switch_channel.c:1844 (sofia/external-lan/7398@10.55.4.5) Callstate Change ACTIVE -> HELD
1548. 2019-06-05 15:33:30.309180 [DEBUG] switch_ivr.c:625 sofia/internal/7667398@185.39.248.196:2658 Command Execute playback(local_stream://default)
1549. EXECUTE sofia/internal/7667398@185.39.248.196:2658 playback(local_stream://default)
1550. 2019-06-05 15:33:30.309180 [DEBUG] mod_local_stream.c:907 Opening Stream [default/8000] 8000hz
1551. 2019-06-05 15:33:30.309180 [DEBUG] switch_ivr_play_say.c:1497 Codec Activated L16@8000hz 1 channels 20ms
1552. 2019-06-05 15:33:30.329170 [NOTICE] switch_core_media.c:15605 Deactivating write resampler
1553. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
1554. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
1555. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
1556. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[G722:9:8000:20:64000:1]
1557. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
1558. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
1559. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
1560. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
1561. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
1562. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
1563. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G722:9:8000:20:64000:1]
1564. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
1565. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
1566. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
1567. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
1568. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
1569. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
1570. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G722:9:8000:20:64000:1]
1571. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
1572. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
1573. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
1574. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
1575. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
1576. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[opus:116:48000:20:0:1]
1577. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[G722:9:8000:20:64000:1]
1578. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMA:8:8000:20:64000:1]
1579. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [iLBC:116:8000:60:0:1]/[PCMU:0:8000:20:64000:1]
1580. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
1581. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
1582. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[opus:116:48000:20:0:1]
1583. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[G722:9:8000:20:64000:1]
1584. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMA:8:8000:20:64000:1]
1585. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:60:8000:1]/[PCMU:0:8000:20:64000:1]
1586. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
1587. 2019-06-05 15:33:30.429173 [WARNING] switch_core_media.c:5551 Crypto not negotiated but required.
1588. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
1589. 2019-06-05 15:33:30.429173 [DEBUG] switch_core_media.c:5795 sofia/external-lan/7398@10.55.4.5 Set 2833 dtmf send payload to 101 recv payload to 101
1590. 2019-06-05 15:33:30.429173 [DEBUG] sofia.c:8216 Reinvite resulted in codec negotiation failure.
1591. nua.c:879 nua_respond() nua: nua_respond: entering
1592. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 488 Not Acceptable Here
1593. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1594. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
1595. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
1596. soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fce74014690) called
1597. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
1598. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 517 bytes of 517 to tcp/10.55.4.5:55848
1599. tport.c:3496 tport_send_msg() tport_vsend returned 517
1600. send 517 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.270906:
1601.    ------------------------------------------------------------------------
1602.    SIP/2.0 488 Not Acceptable Here
1603.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f;rport=55848
1604.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1605.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1606.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1607.    CSeq: 102 INVITE
1608.    User-Agent: FreeSWITCH
1609.    Accept: application/sdp
1610.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
1611.    Supported: timer, path, replaces
1612.    Content-Length: 0
1613.  
1614.    ------------------------------------------------------------------------
1615. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1616. nta.c:6797 incoming_reply() nta: sent 488 Not Acceptable Here for INVITE (102)
1617. nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: init
1618. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 488 Not Acceptable Here
1619. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_active 488 Call active
1620. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called
1621. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
1622. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1623. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1624. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1625. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
1626. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
1627. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74085a80 from (tcp/10.55.4.5:55848) has 457 bytes, veclen = 1
1628. recv 457 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.271982:
1629.    ------------------------------------------------------------------------
1630.    ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
1631.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60e747a318f
1632.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1633.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1634.    Date: Wed, 05 Jun 2019 14:33:30 GMT
1635.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1636.    User-Agent: Cisco-CUCM10.5
1637.    Max-Forwards: 70
1638.    CSeq: 102 ACK
1639.    Allow-Events: presence
1640.    Content-Length: 0
1641.  
1642.    ------------------------------------------------------------------------
1643. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74085a80 (457 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
1644. nta.c:2880 agent_recv_request() nta: received ACK sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 102)
1645. nta.c:3019 agent_recv_request() nta: ACK (102) is going to INVITE (102)
1646. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1647. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1648. 2019-06-05 15:33:30.489166 [DEBUG] sofia.c:7284 Channel sofia/external-lan/7398@10.55.4.5 skipping state [ready][488]
1649. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1650. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1651. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1652. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
1653. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
1654. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74085a80 from (tcp/10.55.4.5:55848) has 975 bytes, veclen = 1
1655. recv 975 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.405514:
1656.    ------------------------------------------------------------------------
1657.    UPDATE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
1658.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60f5cf0f029
1659.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1660.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1661.    Date: Wed, 05 Jun 2019 14:33:30 GMT
1662.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1663.    User-Agent: Cisco-CUCM10.5
1664.    Max-Forwards: 70
1665.    Supported: timer,resource-priority,replaces
1666.   Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
1667.    CSeq: 103 UPDATE
1668.    Call-Info: <urn:x-cisco-remotecc:callinfo>;x-cisco-video-traffic-class=MIXED
1669.    Supported: X-cisco-srtp-fallback
1670.    Supported: Geolocation
1671.    Session-Expires:  1800;refresher=uac
1672.    Min-SE:  1800
1673.    P-Asserted-Identity: "Stephen Barry" <sip:2036964422@10.55.4.5>
1674.    Remote-Party-ID: "Stephen Barry" <sip:2036964422@10.55.4.5>;party=calling;screen=yes;privacy=off
1675.    Contact: <sip:8081@10.55.4.5:5060;transport=tcp>
1676.    Content-Length: 0
1677.  
1678.    ------------------------------------------------------------------------
1679. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74085a80 (975 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
1680. nta.c:2880 agent_recv_request() nta: received UPDATE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 103)
1681. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
1682. nta.c:3060 agent_recv_request() nta: UPDATE (103) going to existing leg
1683. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
1684. nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768])
1685. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
1686. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 606 bytes of 606 to tcp/10.55.4.5:55848
1687. tport.c:3496 tport_send_msg() tport_vsend returned 606
1688. send 606 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.405641:
1689.    ------------------------------------------------------------------------
1690.    SIP/2.0 200 OK
1691.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb60f5cf0f029;rport=55848
1692.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1693.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1694.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1695.    CSeq: 103 UPDATE
1696.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
1697.    User-Agent: FreeSWITCH
1698.    Accept: application/sdp
1699.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
1700.    Require: timer
1701.    Supported: timer, path, replaces
1702.    Session-Expires: 1800;refresher=uac
1703.    Content-Length: 0
1704.  
1705.    ------------------------------------------------------------------------
1706. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1707. nta.c:6797 incoming_reply() nta: sent 200 OK for UPDATE (103)
1708. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_update 200 OK
1709. nta.c:5744 incoming_free() nta: incoming_free(0x7fce740885c0)
1710. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1711. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1712. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
1713. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
1714. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74089e30 from (tcp/10.55.4.5:55848) has 1013 bytes, veclen = 1
1715. recv 1013 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.410746:
1716.    ------------------------------------------------------------------------
1717.    INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
1718.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4
1719.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1720.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1721.    Date: Wed, 05 Jun 2019 14:33:30 GMT
1722.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1723.    Supported: timer,resource-priority,replaces
1724.    User-Agent: Cisco-CUCM10.5
1725.   Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
1726.    CSeq: 104 INVITE
1727.    Max-Forwards: 70
1728.    Expires: 180
1729.    Allow-Events: presence
1730.    Call-Info: <urn:x-cisco-remotecc:callinfo>;x-cisco-video-traffic-class=MIXED
1731.    Supported: X-cisco-srtp-fallback
1732.    Supported: Geolocation
1733.    Session-Expires:  1800;refresher=uac
1734.    Min-SE:  1800
1735.    P-Asserted-Identity: "Stephen Barry" <sip:2036964422@10.55.4.5>
1736.    Remote-Party-ID: "Stephen Barry" <sip:2036964422@10.55.4.5>;party=calling;screen=yes;privacy=off
1737.    Contact: <sip:8081@10.55.4.5:5060;transport=tcp>
1738.    Content-Length: 0
1739.  
1740.    ------------------------------------------------------------------------
1741. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74089e30 (1013 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
1742. nta.c:2880 agent_recv_request() nta: received INVITE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 104)
1743. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
1744. nta.c:3060 agent_recv_request() nta: INVITE (104) going to existing leg
1745. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
1746. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce74014690) called
1747. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_invite 100 Trying
1748. nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: received
1749. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 100 Trying
1750. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1751. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1752. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1753. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1754. 2019-06-05 15:33:30.569165 [INFO] sofia.c:1345 sofia/external-lan/7398@10.55.4.5 Update Caller ID to "Stephen Barry" <2036964422>
1755. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1756. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1757. nua.c:879 nua_respond() nua: nua_respond: entering
1758. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 100 Trying
1759. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1760. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
1761. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
1762. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 355 bytes of 355 to tcp/10.55.4.5:55848
1763. tport.c:3496 tport_send_msg() tport_vsend returned 355
1764. send 355 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.411215:
1765.    ------------------------------------------------------------------------
1766.    SIP/2.0 100 Trying
1767.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
1768.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1769.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1770.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1771.    CSeq: 104 INVITE
1772.    User-Agent: FreeSWITCH
1773.    Content-Length: 0
1774.  
1775.    ------------------------------------------------------------------------
1776. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1777. nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (104)
1778. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
1779. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1780. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1781. 2019-06-05 15:33:30.569165 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [received][100]
1782. nua.c:879 nua_respond() nua: nua_respond: entering
1783. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK
1784. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1785. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
1786. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fce74014690, (nil), 0x7fce7009f09b, -1) called
1787. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
1788. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1789. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
1790. soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fce74014690, 0) called
1791. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fce74014690, soa_generate_offer): called
1792. soa_static.c:1217 offer_answer_step() soa_static(0x7fce74014690, soa_generate_offer): upgrade with local description
1793. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fce6b5e8ab0, (nil), ""): called
1794. soa_static.c:1446 offer_answer_step() soa_static(0x7fce74014690, soa_generate_offer): storing local description
1795. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [(nil)], [0x7fce6b5eac38], [0x7fce6b5eac34]) called
1796. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
1797. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
1798. tport.c:3496 tport_send_msg() tport_vsend returned 839
1799. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.411597:
1800.    ------------------------------------------------------------------------
1801.    SIP/2.0 200 OK
1802.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
1803.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1804.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1805.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1806.    CSeq: 104 INVITE
1807.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
1808.    User-Agent: FreeSWITCH
1809.    Accept: application/sdp
1810.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
1811.    Require: timer
1812.    Supported: timer, path, replaces
1813.    Session-Expires: 1800;refresher=uac
1814.    Content-Type: application/sdp
1815.    Content-Disposition: session
1816.    Content-Length: 170
1817.  
1818.    v=0
1819.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
1820.    s=FreeSWITCH
1821.    c=IN IP4 10.55.4.7
1822.    t=0 0
1823.    m=audio 26324 RTP/AVP 9
1824.    a=rtpmap:9 G722/8000
1825.    a=inactive
1826.    a=ptime:20
1827.    ------------------------------------------------------------------------
1828. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1829. nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (104)
1830. nta.c:1348 set_timeout() nta: timer shortened to 500 ms
1831. nua_session.c:4145 signal_call_state_change() nua(0x7fce74002fd0): ready call updated: completed sent offer
1832. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fce74014690, [0x7fce6b5eace8], [0x7fce6b5eacf0], [(nil)]) called
1833. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 OK
1834. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1835. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1836. 2019-06-05 15:33:30.629163 [DEBUG] sofia.c:7291 Channel sofia/external-lan/7398@10.55.4.5 entering state [completed][200]
1837. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1838. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce740022f0): events IN
1839. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce740022f0)
1840. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce740022f0) msg 0x7fce74088210 from (tcp/10.55.4.5:55848) has 516 bytes, veclen = 1
1841. recv 516 bytes from tcp/[10.55.4.5]:55848 at 15:33:30.491968:
1842.    ------------------------------------------------------------------------
1843.    BYE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0
1844.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb61177ff7dcb
1845.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1846.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1847.    Date: Wed, 05 Jun 2019 14:33:30 GMT
1848.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1849.    User-Agent: Cisco-CUCM10.5
1850.    Max-Forwards: 70
1851.    P-Asserted-Identity: "Stephen Barry" <sip:7398@10.55.4.5>
1852.    CSeq: 105 BYE
1853.    Reason: Q.850;cause=47
1854.    Content-Length: 0
1855.  
1856.    ------------------------------------------------------------------------
1857. tport.c:3027 tport_deliver() tport_deliver(0x7fce740022f0): msg 0x7fce74088210 (516 bytes) from tcp/10.55.4.5:55848/sip next=(nil)
1858. nta.c:2880 agent_recv_request() nta: received BYE sip:7667398@10.55.4.7:5080;transport=tcp SIP/2.0 (CSeq 105)
1859. nta.c:3248 agent_aliases() nta: canonizing sip:7667398@10.55.4.7:5080 with contact
1860. nta.c:3060 agent_recv_request() nta: BYE (105) going to existing leg
1861. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
1862. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_bye 100 Trying
1863. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1864. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1865. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1866. 2019-06-05 15:33:30.709163 [DEBUG] switch_channel.c:2029 (sofia/external-lan/7398@10.55.4.5) Callstate Change HELD -> UNHELD
1867. 2019-06-05 15:33:30.709163 [NOTICE] sofia.c:1079 Hangup sofia/external-lan/7398@10.55.4.5 [CS_EXECUTE] [UNKNOWN]
1868. 2019-06-05 15:33:30.709163 [DEBUG] mod_hash.c:297 Usage for voip.mydomain.com_7667398 is now 0
1869. nua.c:879 nua_respond() nua: nua_respond: entering
1870. nua_stack.c:573 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_respond 200 OK
1871. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1872. soa.c:403 soa_set_params() soa_set_params(static::0x7fce74014690, ...) called
1873. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_respond
1874. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
1875. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
1876. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1877. nua_stack.c:529 nua_signal() nua(0x7fce74002fd0): sent signal r_destroy
1878. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 472 bytes of 472 to tcp/10.55.4.5:55848
1879. tport.c:3496 tport_send_msg() tport_vsend returned 472
1880. send 472 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.552443:
1881.    ------------------------------------------------------------------------
1882.    SIP/2.0 200 OK
1883.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb61177ff7dcb;rport=55848
1884.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
1885.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
1886.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
1887.    CSeq: 105 BYE
1888.    User-Agent: FreeSWITCH
1889.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
1890.    Supported: timer, path, replaces
1891.    Content-Length: 0
1892.  
1893.    ------------------------------------------------------------------------
1894. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
1895. nta.c:6797 incoming_reply() nta: sent 200 OK for BYE (105)
1896. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce74002fd0): removing session usage
1897. nua_session.c:4139 signal_call_state_change() nua(0x7fce74002fd0): call state changed: ready -> terminated
1898. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_state 200 Session Terminated
1899. nua_stack.c:271 nua_stack_event() nua(0x7fce74002fd0): event i_terminated 200 Session Terminated
1900. soa.c:356 soa_destroy() soa_destroy(static::0x7fce74014690) called
1901. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fce740033f0)
1902. nta.c:5744 incoming_free() nta: incoming_free(0x7fce74014f80)
1903. nua_stack.c:569 nua_stack_signal() nua(0x7fce74002fd0): recv signal r_destroy
1904. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
1905. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external-lan/7398@10.55.4.5]
1906. 2019-06-05 15:33:30.709163 [NOTICE] switch_ivr_bridge.c:932 Hangup sofia/internal/7667398@185.39.248.196:2658 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
1907. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:1881 sofia/internal/7667398@185.39.248.196:2658 skip receive message [UNBRIDGE] (channel is hungup already)
1908. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:1884 sofia/external-lan/7398@10.55.4.5 skip receive message [UNBRIDGE] (channel is hungup already)
1909. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:2887 sofia/external-lan/7398@10.55.4.5 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
1910. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:650 (sofia/external-lan/7398@10.55.4.5) State EXECUTE going to sleep
1911. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_HANGUP (Cur 2 Tot 314)
1912. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:847 (sofia/external-lan/7398@10.55.4.5) Callstate Change UNHELD -> HANGUP
1913. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/external-lan/7398@10.55.4.5) State HANGUP
1914. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:449 Channel sofia/external-lan/7398@10.55.4.5 hanging up, cause: UNKNOWN
1915. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:60 sofia/external-lan/7398@10.55.4.5 Standard HANGUP, cause: UNKNOWN
1916. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/external-lan/7398@10.55.4.5) State HANGUP going to sleep
1917. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:780 Hangup Command with no Session lua(app.lua hangup):
1918.  
1919. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:619 (sofia/external-lan/7398@10.55.4.5) State Change CS_HANGUP -> CS_REPORTING
1920. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_REPORTING (Cur 2 Tot 314)
1921. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/external-lan/7398@10.55.4.5) State REPORTING
1922. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_play_say.c:1941 done playing file local_stream://default
1923. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:2887 sofia/internal/7667398@185.39.248.196:2658 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
1924. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:572 sofia/internal/7667398@185.39.248.196:2658 skip receive message [BRIDGE] (channel is hungup already)
1925. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr.c:669 sofia/internal/7667398@185.39.248.196:2658 skip receive message [AUDIO_SYNC] (channel is hungup already)
1926. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:831 sofia/internal/7667398@185.39.248.196:2658 ending bridge by request from read function
1927. 2019-06-05 15:33:30.709163 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/7667398@185.39.248.196:2658]
1928. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/7667398@185.39.248.196:2658) State EXCHANGE_MEDIA going to sleep
1929. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_HANGUP (Cur 2 Tot 314)
1930. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/7667398@185.39.248.196:2658) Callstate Change ACTIVE -> HANGUP
1931. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/7667398@185.39.248.196:2658) State HANGUP
1932. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:443 sofia/internal/7667398@185.39.248.196:2658 Overriding SIP cause 480 with 200 from the other leg
1933. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:449 Channel sofia/internal/7667398@185.39.248.196:2658 hanging up, cause: NORMAL_CLEARING
1934. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/7667398@185.39.248.196:2658
1935. nua.c:645 nua_bye() nua: nua_bye: entering
1936. nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_bye
1937. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
1938. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
1939. nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_bye
1940. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:60 sofia/internal/7667398@185.39.248.196:2658 Standard HANGUP, cause: NORMAL_CLEARING
1941. soa.c:1784 soa_terminate() soa_terminate(static::0x7fce600921a0) called
1942. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fce600921a0) called
1943. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/7667398@185.39.248.196:2658) State HANGUP going to sleep
1944. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
1945. tport.c:4592 tport_by_name() tport(0x7fce600466b0): found 0x7fce6007ac40 by name tls/185.39.248.196:2658
1946. tport.c:3261 tport_tsend() tport_tsend(0x7fce6007ac40) tpn = tls/185.39.248.196:2658
1947. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_HANGUP -> CS_REPORTING
1948. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce6007ba80 0x7fce6005b5c0 606 (606)
1949. tport.c:3598 tport_vsend() tport_vsend(0x7fce6007ac40): 606 bytes of 606 to tls/185.39.248.196:2658
1950. tport.c:3496 tport_send_msg() tport_vsend returned 606
1951. send 606 bytes to tls/[185.39.248.196]:2658 at 15:33:30.566247:
1952.    ------------------------------------------------------------------------
1953.    BYE sip:7667398@185.39.248.196:2658;transport=tls SIP/2.0
1954.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport;branch=z9hG4bKc1aFc6UrpZNcF
1955.    Max-Forwards: 70
1956.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
1957.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
1958.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
1959.    CSeq: 5318807 BYE
1960.    User-Agent: FreeSWITCH
1961.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1962.    Supported: timer, path, replaces
1963.    Reason: Q.850;cause=47
1964.    Content-Length: 0
1965.  
1966.    ------------------------------------------------------------------------
1967. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
1968. nta.c:8310 outgoing_send() nta: sent BYE (5318807) to tls/185.39.248.196:2658
1969. tport.c:4164 tport_pend() tport_pend(0x7fce6007ac40): pending 0x7fce6007dec0 for tls/185.39.248.196:2658 (already 0)
1970. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_REPORTING (Cur 2 Tot 314)
1971. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/7667398@185.39.248.196:2658) State REPORTING
1972. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:174 sofia/internal/7667398@185.39.248.196:2658 Standard REPORTING, cause: NORMAL_CLEARING
1973. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/7667398@185.39.248.196:2658) State REPORTING going to sleep
1974. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/7667398@185.39.248.196:2658) State Change CS_REPORTING -> CS_DESTROY
1975. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_session.c:1715 Session 314 (sofia/internal/7667398@185.39.248.196:2658) Locked, Waiting on external entities
1976. 2019-06-05 15:33:30.709163 [NOTICE] switch_core_session.c:1733 Session 314 (sofia/internal/7667398@185.39.248.196:2658) Ended
1977. 2019-06-05 15:33:30.709163 [NOTICE] switch_core_session.c:1737 Close Channel sofia/internal/7667398@185.39.248.196:2658 [CS_DESTROY]
1978. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/7667398@185.39.248.196:2658) Running State Change CS_DESTROY (Cur 1 Tot 314)
1979. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/7667398@185.39.248.196:2658) State DESTROY
1980. 2019-06-05 15:33:30.709163 [DEBUG] mod_sofia.c:354 sofia/internal/7667398@185.39.248.196:2658 SOFIA DESTROY
1981. 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[416] PLC[0] FEC[0]
1982. 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
1983. 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
1984. 2019-06-05 15:33:30.709163 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[436] Bytes encoded[12371] Encoded length ms[8720] Average encoded bitrate bps[12371]
1985. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:181 sofia/internal/7667398@185.39.248.196:2658 Standard DESTROY
1986. 2019-06-05 15:33:30.709163 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/7667398@185.39.248.196:2658) State DESTROY going to sleep
1987. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:174 sofia/external-lan/7398@10.55.4.5 Standard REPORTING, cause: UNKNOWN
1988. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:935 (sofia/external-lan/7398@10.55.4.5) State REPORTING going to sleep
1989. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:610 (sofia/external-lan/7398@10.55.4.5) State Change CS_REPORTING -> CS_DESTROY
1990. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_session.c:1715 Session 313 (sofia/external-lan/7398@10.55.4.5) Locked, Waiting on external entities
1991. 2019-06-05 15:33:30.729171 [NOTICE] switch_core_session.c:1733 Session 313 (sofia/external-lan/7398@10.55.4.5) Ended
1992. 2019-06-05 15:33:30.729171 [NOTICE] switch_core_session.c:1737 Close Channel sofia/external-lan/7398@10.55.4.5 [CS_DESTROY]
1993. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:738 (sofia/external-lan/7398@10.55.4.5) Running State Change CS_DESTROY (Cur 0 Tot 314)
1994. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:748 (sofia/external-lan/7398@10.55.4.5) State DESTROY
1995. 2019-06-05 15:33:30.729171 [DEBUG] mod_sofia.c:354 sofia/external-lan/7398@10.55.4.5 SOFIA DESTROY
1996. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:181 sofia/external-lan/7398@10.55.4.5 Standard DESTROY
1997. 2019-06-05 15:33:30.729171 [DEBUG] switch_core_state_machine.c:748 (sofia/external-lan/7398@10.55.4.5) State DESTROY going to sleep
1998. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce6007ac40): events IN
1999. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce6007ac40)
2000. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce6007ac40): tls_read() returned 599
2001. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce6007ac40) msg 0x7fce60082d70 from (tls/185.39.248.196:2658) has 599 bytes, veclen = 1
2002. recv 599 bytes from tls/[185.39.248.196]:2658 at 15:33:30.640195:
2003.    ------------------------------------------------------------------------
2004.    SIP/2.0 200 OK
2005.    Via: SIP/2.0/TLS 185.39.250.165:5061;rport=5061;branch=z9hG4bKc1aFc6UrpZNcF;received=185.39.250.165
2006.    Contact: <sip:7667398@185.39.248.196:2658;transport=tls>
2007.    From: "Stephen Barry" <sip:7398@voip.mydomain.com>;tag=pU8rDB8DUHjFe
2008.    Call-ID: b2998455-0241-1238-e9ba-005056860fd6
2009.    CSeq: 5318807 BYE
2010.    To: <sip:7667398@185.39.248.196:2658;rinstance=117BFF20;transport=tls>;tag=AFAB2EFC86E53DF36B3DE9E22393BB2C
2011.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
2012.    Supported: replaces, path
2013.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 9; arm64-v8a)
2014.    Content-Length: 0
2015.  
2016.    ------------------------------------------------------------------------
2017. tport.c:3027 tport_deliver() tport_deliver(0x7fce6007ac40): msg 0x7fce60082d70 (599 bytes) from tls/185.39.248.196:2658/sips next=(nil)
2018. nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (5318807)
2019. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
2020. nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 74.007 ms
2021. tport.c:4226 tport_release() tport_release(0x7fce6007ac40): 0x7fce6007dec0 by 0x7fce6007cd00 with 0x7fce60082d70
2022. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event r_bye 200 OK
2023. nua_session.c:4139 signal_call_state_change() nua(0x7fce6c02f9a0): call state changed: terminating -> terminated
2024. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_state 200 to BYE
2025. nua_stack.c:271 nua_stack_event() nua(0x7fce6c02f9a0): event i_terminated 200 to BYE
2026. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce6c02f9a0): removing session usage
2027. soa.c:356 soa_destroy() soa_destroy(static::0x7fce600921a0) called
2028. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2029. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fce60050880)
2030. nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7fce6c02f9a0
2031. nta.c:8728 outgoing_free() nta: outgoing_free(0x7fce6007cd00)
2032. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2033. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2034. tport.c:2298 tport_set_secondary_timer() tport(0x7fce6007ac40): reset timer
2035. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2036. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2037. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2038. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2039. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2040. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2041. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2042. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2043. nua_stack.c:569 nua_stack_signal() nua(0x7fce6c02f9a0): recv signal r_destroy
2044. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
2045. nua_stack.c:529 nua_signal() nua(0x7fce6c02f9a0): sent signal r_destroy
2046. nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
2047. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
2048. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
2049. tport.c:3496 tport_send_msg() tport_vsend returned 839
2050. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:30.911677:
2051.    ------------------------------------------------------------------------
2052.    SIP/2.0 200 OK
2053.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
2054.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
2055.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
2056.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
2057.    CSeq: 104 INVITE
2058.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
2059.    User-Agent: FreeSWITCH
2060.    Accept: application/sdp
2061.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
2062.    Require: timer
2063.    Supported: timer, path, replaces
2064.    Session-Expires: 1800;refresher=uac
2065.    Content-Type: application/sdp
2066.    Content-Disposition: session
2067.    Content-Length: 170
2068.  
2069.    v=0
2070.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
2071.    s=FreeSWITCH
2072.    c=IN IP4 10.55.4.7
2073.    t=0 0
2074.    m=audio 26324 RTP/AVP 9
2075.    a=rtpmap:9 G722/8000
2076.    a=inactive
2077.    a=ptime:20
2078.    ------------------------------------------------------------------------
2079. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
2080. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fce6b5eac50)
2081. nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 1/2 free
2082. nta.c:1296 agent_timer() nta: timer set next to 1000 ms
2083. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60053a50): events IN
2084. tport.c:2159 tport_shutdown0() tport_shutdown0(0x7fce60053a50, 2)
2085. tport.c:2092 tport_close() tport_close(0x7fce60053a50): tls/162.243.35.55:64178/sips
2086. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN
2087. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50)
2088. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 594
2089. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 594 bytes, veclen = 1
2090. recv 594 bytes from tls/[185.39.250.164]:41117 at 15:33:31.430496:
2091.    ------------------------------------------------------------------------
2092.    REGISTER sip:voip.mydomain.com SIP/2.0
2093.    Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bK76hEepoHW5dMPtUM;rport
2094.    Contact: <sip:766@185.39.250.164:41117;rinstance=599D32E4;transport=tls>;expires=600;video
2095.    Max-Forwards: 70
2096.    From: <sip:766@voip.mydomain.com>;tag=FE14135E45D208D6CE5AC4C4FC9EE551
2097.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
2098.    Supported: replaces, path
2099.    To: <sip:766@voip.mydomain.com>
2100.    Expires: 600
2101.    Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA
2102.    CSeq: 503 REGISTER
2103.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 8.1.0; arm64-v8a)
2104.    Content-Length: 0
2105.  
2106.    ------------------------------------------------------------------------
2107. tport.c:3027 tport_deliver() tport_deliver(0x7fce60055b50): msg 0x7fce600332f0 (594 bytes) from tls/185.39.250.164:41117/sips next=(nil)
2108. nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 503)
2109. nta.c:3174 agent_check_request_via() nta: Via check: received=185.39.250.164
2110. nta.c:3085 agent_recv_request() nta: REGISTER (503) going to a default leg
2111. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
2112. nua_stack.c:899 nh_create() nua: nh_create: entering
2113. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
2114. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
2115. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce60037d30) called
2116. soa.c:403 soa_set_params() soa_set_params(static::0x7fce6007cb80, ...) called
2117. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce60037d30): adding registrar usage
2118. tport.c:4164 tport_pend() tport_pend(0x7fce60055b50): pending (nil) for tls/185.39.250.164:41117 (already 0)
2119. nua_stack.c:271 nua_stack_event() nua(0x7fce60037d30): event i_register 100 Trying
2120. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
2121. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2122. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2123. nua.c:879 nua_respond() nua: nua_respond: entering
2124. nua_stack.c:529 nua_signal() nua(0x7fce60037d30): sent signal r_respond
2125. nua_stack.c:573 nua_stack_signal() nua(0x7fce60037d30): recv signal r_respond 401 Unauthorized
2126. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
2127. soa.c:403 soa_set_params() soa_set_params(static::0x7fce6007cb80, ...) called
2128. 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:1798 SIP auth challenge (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 185.39.250.164
2129. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2130. nua_stack.c:529 nua_signal() nua(0x7fce60037d30): sent signal r_destroy
2131. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2132. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2133. tport.c:3261 tport_tsend() tport_tsend(0x7fce60055b50) tpn = TLS/185.39.250.164:41117
2134. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722a0 129 (129)
2135. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600c074e 71 (71)
2136. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072321 50 (50)
2137. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600c081d 71 (71)
2138. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072353 313 (313)
2139. tport.c:3598 tport_vsend() tport_vsend(0x7fce60055b50): 634 bytes of 634 to tls/185.39.250.164:41117
2140. tport.c:3496 tport_send_msg() tport_vsend returned 634
2141. send 634 bytes to tls/[185.39.250.164]:41117 at 15:33:31.430888:
2142.    ------------------------------------------------------------------------
2143.    SIP/2.0 401 Unauthorized
2144.    Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bK76hEepoHW5dMPtUM;rport=41117;received=185.39.250.164
2145.    From: <sip:766@voip.mydomain.com>;tag=FE14135E45D208D6CE5AC4C4FC9EE551
2146.    To: <sip:766@voip.mydomain.com>;tag=Spm3jvtrjcN7g
2147.    Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA
2148.    CSeq: 503 REGISTER
2149.    User-Agent: FreeSWITCH
2150.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
2151.    Supported: timer, path, replaces
2152.    WWW-Authenticate: Digest realm="voip.mydomain.com", nonce="831c4ee7-39bc-4fab-95f9-57906f1cd317", algorithm=MD5, qop="auth"
2153.    Content-Length: 0
2154.  
2155.    ------------------------------------------------------------------------
2156. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
2157. nta.c:6797 incoming_reply() nta: sent 401 Unauthorized for REGISTER (503)
2158. nta.c:5744 incoming_free() nta: incoming_free(0x7fce60052510)
2159. nua_stack.c:569 nua_stack_signal() nua(0x7fce60037d30): recv signal r_destroy
2160. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce60037d30): removing registrar usage
2161. tport.c:4226 tport_release() tport_release(0x7fce60055b50): (nil) by 0x7fce60037d30 with (nil)
2162. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
2163. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
2164. soa.c:356 soa_destroy() soa_destroy(static::0x7fce6007cb80) called
2165. tport.c:2777 tport_wakeup() tport_wakeup(0x7fce60055b50): events IN
2166. tport.c:2868 tport_recv_event() tport_recv_event(0x7fce60055b50)
2167. tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7fce60055b50): tls_read() returned 842
2168. tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fce60055b50) msg 0x7fce600332f0 from (tls/185.39.250.164:41117) has 842 bytes, veclen = 1
2169. recv 842 bytes from tls/[185.39.250.164]:41117 at 15:33:31.442976:
2170.    ------------------------------------------------------------------------
2171.    REGISTER sip:voip.mydomain.com SIP/2.0
2172.    Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bKWFMe5vUSuAcJS5LP;rport
2173.    Contact: <sip:766@185.39.250.164:41117;rinstance=599D32E4;transport=tls>;expires=600;video
2174.    Max-Forwards: 70
2175.    From: <sip:766@voip.mydomain.com>;tag=FE14135E45D208D6CE5AC4C4FC9EE551
2176.   Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
2177.    Supported: replaces, path
2178.    To: <sip:766@voip.mydomain.com>
2179.    Expires: 600
2180.    Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA
2181.    CSeq: 504 REGISTER
2182.    Authorization: Digest username="766",realm="voip.mydomain.com",algorithm=MD5,uri="sip:voip.mydomain.com",nonce="831c4ee7-39bc-4fab-95f9-57906f1cd317",qop=auth,cnonce="XPfSu8WgFUtrKcJ1eXtLtrUz",nc=00000001,response="41f1e87f8e30cd2b0d5cf1b807f361b4"
2183.    User-Agent: Groundwire/5.2.14 (build 1243766; Android 8.1.0; arm64-v8a)
2184.    Content-Length: 0
2185.  
2186.    ------------------------------------------------------------------------
2187. tport.c:3027 tport_deliver() tport_deliver(0x7fce60055b50): msg 0x7fce600332f0 (842 bytes) from tls/185.39.250.164:41117/sips next=(nil)
2188. nta.c:2880 agent_recv_request() nta: received REGISTER sip:voip.mydomain.com SIP/2.0 (CSeq 504)
2189. nta.c:3174 agent_check_request_via() nta: Via check: received=185.39.250.164
2190. nta.c:3085 agent_recv_request() nta: REGISTER (504) going to a default leg
2191. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
2192. nua_stack.c:899 nh_create() nua: nh_create: entering
2193. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
2194. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
2195. soa.c:280 soa_clone() soa_clone(static::0x7fce60096e10, 0x7fce6007dde0, 0x7fce6005d220) called
2196. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
2197. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fce6005d220): adding registrar usage
2198. tport.c:4164 tport_pend() tport_pend(0x7fce60055b50): pending (nil) for tls/185.39.250.164:41117 (already 0)
2199. nua_stack.c:271 nua_stack_event() nua(0x7fce6005d220): event i_register 100 Trying
2200. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
2201. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2202. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2203. 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:2935 Can't find user [766@voip.mydomain.com] from 185.39.250.164
2204. You must define a domain called 'voip.mydomain.com' in your directory and add a user with the id="766" attribute
2205. and you must configure your device to use the proper domain in it's authentication credentials.
2206. nua.c:879 nua_respond() nua: nua_respond: entering
2207. nua_stack.c:573 nua_stack_signal() nua(0x7fce6005d220): recv signal r_respond 403 Forbidden
2208. nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
2209. soa.c:403 soa_set_params() soa_set_params(static::0x7fce600921a0, ...) called
2210. tport.c:3261 tport_tsend() tport_tsend(0x7fce60055b50) tpn = TLS/185.39.250.164:41117
2211. nua_stack.c:529 nua_signal() nua(0x7fce6005d220): sent signal r_respond
2212. 2019-06-05 15:33:31.589166 [WARNING] sofia_reg.c:1743 SIP auth failure (REGISTER) on sofia profile 'internal' for [766@voip.mydomain.com] from ip 185.39.250.164
2213. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072230 126 (126)
2214. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2215. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072ece 71 (71)
2216. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722ae 50 (50)
2217. nua_stack.c:529 nua_signal() nua(0x7fce6005d220): sent signal r_destroy
2218. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2219. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce60072f9d 71 (71)
2220. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2221. tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7fce60038540 0x7fce600722e0 189 (189)
2222. tport.c:3598 tport_vsend() tport_vsend(0x7fce60055b50): 507 bytes of 507 to tls/185.39.250.164:41117
2223. tport.c:3496 tport_send_msg() tport_vsend returned 507
2224. send 507 bytes to tls/[185.39.250.164]:41117 at 15:33:31.446079:
2225.    ------------------------------------------------------------------------
2226.    SIP/2.0 403 Forbidden
2227.    Via: SIP/2.0/TLS 10.44.4.218:41117;branch=z9hG4bKWFMe5vUSuAcJS5LP;rport=41117;received=185.39.250.164
2228.    From: <sip:766@voip.mydomain.com>;tag=FE14135E45D208D6CE5AC4C4FC9EE551
2229.    To: <sip:766@voip.mydomain.com>;tag=tZDvmQBvFNBtc
2230.    Call-ID: B5922A752C0F91D4693A3EC8E2E8C612282D6CEA
2231.    CSeq: 504 REGISTER
2232.    User-Agent: FreeSWITCH
2233.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
2234.    Supported: timer, path, replaces
2235.    Content-Length: 0
2236.  
2237.    ------------------------------------------------------------------------
2238. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
2239. nta.c:6797 incoming_reply() nta: sent 403 Forbidden for REGISTER (504)
2240. nta.c:5744 incoming_free() nta: incoming_free(0x7fce60037d30)
2241. nua_stack.c:569 nua_stack_signal() nua(0x7fce6005d220): recv signal r_destroy
2242. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fce6005d220): removing registrar usage
2243. tport.c:4226 tport_release() tport_release(0x7fce60055b50): (nil) by 0x7fce6005d220 with (nil)
2244. tport.c:2298 tport_set_secondary_timer() tport(0x7fce60055b50): reset timer
2245. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
2246. soa.c:356 soa_destroy() soa_destroy(static::0x7fce600921a0) called
2247. nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
2248. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
2249. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
2250. tport.c:3496 tport_send_msg() tport_vsend returned 839
2251. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:31.911851:
2252.    ------------------------------------------------------------------------
2253.    SIP/2.0 200 OK
2254.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
2255.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
2256.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
2257.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
2258.    CSeq: 104 INVITE
2259.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
2260.    User-Agent: FreeSWITCH
2261.    Accept: application/sdp
2262.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
2263.    Require: timer
2264.    Supported: timer, path, replaces
2265.    Session-Expires: 1800;refresher=uac
2266.    Content-Type: application/sdp
2267.    Content-Disposition: session
2268.    Content-Length: 170
2269.  
2270.    v=0
2271.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
2272.    s=FreeSWITCH
2273.    c=IN IP4 10.55.4.7
2274.    t=0 0
2275.    m=audio 26324 RTP/AVP 9
2276.    a=rtpmap:9 G722/8000
2277.    a=inactive
2278.    a=ptime:20
2279.    ------------------------------------------------------------------------
2280. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
2281. nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free
2282. nta.c:1296 agent_timer() nta: timer set next to 2000 ms
2283. nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
2284. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
2285. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
2286. tport.c:3496 tport_send_msg() tport_vsend returned 839
2287. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:33.911871:
2288.    ------------------------------------------------------------------------
2289.    SIP/2.0 200 OK
2290.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
2291.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
2292.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
2293.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
2294.    CSeq: 104 INVITE
2295.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
2296.    User-Agent: FreeSWITCH
2297.    Accept: application/sdp
2298.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
2299.    Require: timer
2300.    Supported: timer, path, replaces
2301.    Session-Expires: 1800;refresher=uac
2302.    Content-Type: application/sdp
2303.    Content-Disposition: session
2304.    Content-Length: 170
2305.  
2306.    v=0
2307.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
2308.    s=FreeSWITCH
2309.    c=IN IP4 10.55.4.7
2310.    t=0 0
2311.    m=audio 26324 RTP/AVP 9
2312.    a=rtpmap:9 G722/8000
2313.    a=inactive
2314.    a=ptime:20
2315.    ------------------------------------------------------------------------
2316. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
2317. nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free
2318. nta.c:1296 agent_timer() nta: timer set next to 4000 ms
2319. nta.c:7002 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
2320. tport.c:3261 tport_tsend() tport_tsend(0x7fce740022f0) tpn = TCP/10.55.4.5:55848
2321. tport.c:3598 tport_vsend() tport_vsend(0x7fce740022f0): 839 bytes of 839 to tcp/10.55.4.5:55848
2322. tport.c:3496 tport_send_msg() tport_vsend returned 839
2323. send 839 bytes to tcp/[10.55.4.5]:55848 at 15:33:37.911921:
2324.    ------------------------------------------------------------------------
2325.    SIP/2.0 200 OK
2326.    Via: SIP/2.0/TCP 10.55.4.5:5060;branch=z9hG4bKb610242aa3f4;rport=55848
2327.    From: "Stephen Barry" <sip:7398@10.55.4.5>;tag=3080835~2dea21b6-791b-4f4f-b7d1-86901784c36a-37256925
2328.    To: <sip:7667398@10.55.4.7>;tag=7c9UFg3rKvmNQ
2329.    Call-ID: d9c36380-cf71d2ac-5887-504370a@10.55.4.5
2330.    CSeq: 104 INVITE
2331.    Contact: <sip:7667398@10.55.4.7:5080;transport=tcp>
2332.    User-Agent: FreeSWITCH
2333.    Accept: application/sdp
2334.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
2335.    Require: timer
2336.    Supported: timer, path, replaces
2337.    Session-Expires: 1800;refresher=uac
2338.    Content-Type: application/sdp
2339.    Content-Disposition: session
2340.    Content-Length: 170
2341.  
2342.    v=0
2343.    o=FreeSWITCH 1559718872 1559718874 IN IP4 10.55.4.7
2344.    s=FreeSWITCH
2345.    c=IN IP4 10.55.4.7
2346.    t=0 0
2347.    m=audio 26324 RTP/AVP 9
2348.    a=rtpmap:9 G722/8000
2349.    a=inactive
2350.    a=ptime:20
2351.    ------------------------------------------------------------------------
2352. tport.c:2298 tport_set_secondary_timer() tport(0x7fce740022f0): reset timer
2353. nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free
2354. nta.c:1296 agent_timer() nta: timer set next to 4000 ms
2355. freeswitch@fpbx01>
2356.