1. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
2. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
3. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0018400 from (udp/10.3.2.4:5060) has 500 bytes, veclen = 1
4. recv 500 bytes from udp/[10.95.2.2]:5060 at 17:20:41.280764:
5.    ------------------------------------------------------------------------
6.    INVITE sip:30161@10.3.2.4 SIP/2.0
7.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
8.    Max-Forwards: 70
9.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
10.    To: <sip:30161@10.3.2.4>
11.    Contact: <sip:100201@10.95.2.2:5060>
12.    Call-ID: 100201@10.95.2.2:5060
13.    CSeq: 13 INVITE
14.    User-Agent: TATTILE PBX v.3.4
15.    Content-Type: application/sdp
16.    Content-Length: 143
17.  
18.    v=0
19.    o=root 1 2 IN IP4 10.95.2.2
20.    s=SIP Call
21.    c=IN IP4 10.95.2.2
22.    t=0 0
23.    m=audio 7068 RTP/AVP 0
24.    a=rtpmap:0 PCMU/8000
25.    a=ptime:20
26.    a=sendrecv
27.    ------------------------------------------------------------------------
28. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0018400 (500 bytes) from udp/10.95.2.2:5060/sip next=(nil)
29. nta.c:2880 agent_recv_request() nta: received INVITE sip:30161@10.3.2.4 SIP/2.0 (CSeq 13)
30. nta.c:3248 agent_aliases() nta: canonizing sip:30161@10.3.2.4 with contact
31. nta.c:3085 agent_recv_request() nta: INVITE (13) going to a default leg
32. nta.c:1348 set_timeout() nta: timer shortened to 200 ms
33. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
34. nua_stack.c:899 nh_create() nua: nh_create: entering
35. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
36. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
37. soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0da00130b0) called
38. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017b10, ...) called
39. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da0022e90)
40. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f0da0017b10) called
41. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f0da0017b10, (nil), 0x7f0da0013f85, 143) called
42. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f0da00130b0): adding session usage
43. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
44. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
45. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
46. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 243 bytes of 243 to udp/10.95.2.2:5060
47. tport.c:3492 tport_send_msg() tport_vsend returned 243
48. send 243 bytes to udp/[10.95.2.2]:5060 at 17:20:41.280927:
49.    ------------------------------------------------------------------------
50.    SIP/2.0 100 Trying
51.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
52.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
53.    To: <sip:30161@10.3.2.4>
54.    Call-ID: 100201@10.95.2.2:5060
55.    CSeq: 13 INVITE
56.    User-Agent: ECSCore
57.    Content-Length: 0
58.  
59.    ------------------------------------------------------------------------
60. nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (13)
61. nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_invite 100 Trying
62. nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: init -> received, received offer
63. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f0da0017b10, [0x7f0daedef8c8], [0x7f0daedef8d0], [(nil)]) called
64. nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_state 100 Trying
65. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
66. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
67. 2017-10-17 17:20:41.272585 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/100201@10.95.2.2 [523d784a-72fd-46f0-9ddd-408bc71763eb]
68. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
69. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_NEW (Cur 1 Tot 25)
70. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
71. 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:9834 sofia/internal/100201@10.95.2.2 receiving invite from 10.95.2.2:5060 version: 1.6.17 git eb93b81 2017-05-08 21:44:33Z 64bit
72. 2017-10-17 17:20:41.272585 [ALERT] switch_core_media.c:447 Looking for zrtp-hash
73. 2017-10-17 17:20:41.272585 [ALERT] switch_core_media.c:402 Deciding whether to pass zrtp-hash between legs
74. 2017-10-17 17:20:41.272585 [ALERT] switch_core_media.c:404 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
75. 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:9950 IP 10.95.2.2 Approved by acl "domains[]". Access Granted.
76. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
77. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
78. 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:7048 Channel sofia/internal/100201@10.95.2.2 entering state [received][100]
79. 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:7058 Remote SDP:
80. v=0
81. o=root 1 2 IN IP4 10.95.2.2
82. s=SIP Call
83. c=IN IP4 10.95.2.2
84. t=0 0
85. m=audio 7068 RTP/AVP 0
86. a=rtpmap:0 PCMU/8000
87. a=ptime:20
88.  
89. 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:7450 (sofia/internal/100201@10.95.2.2) State Change CS_NEW -> CS_INIT
90. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
91. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/100201@10.95.2.2) State NEW
92. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_INIT (Cur 1 Tot 25)
93. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100201@10.95.2.2) State INIT
94. 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:90 sofia/internal/100201@10.95.2.2 SOFIA INIT
95. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:40 sofia/internal/100201@10.95.2.2 Standard INIT
96. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100201@10.95.2.2) State Change CS_INIT -> CS_ROUTING
97. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100201@10.95.2.2) State INIT going to sleep
98. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_ROUTING (Cur 1 Tot 25)
99. 2017-10-17 17:20:41.272585 [DEBUG] switch_channel.c:2249 (sofia/internal/100201@10.95.2.2) Callstate Change DOWN -> RINGING
100. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100201@10.95.2.2) State ROUTING
101. 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:143 sofia/internal/100201@10.95.2.2 SOFIA ROUTING
102. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:236 sofia/internal/100201@10.95.2.2 Standard ROUTING
103. 2017-10-17 17:20:41.272585 [INFO] mod_dialplan_xml.c:637 Processing 100201 <100201>->30161 in context blackhole
104. Dialplan: sofia/internal/100201@10.95.2.2 parsing [blackhole->test] continue=false
105. Dialplan: sofia/internal/100201@10.95.2.2 Regex (PASS) [test] destination_number(30161) =~ /.*/ break=on-false
106. Dialplan: sofia/internal/100201@10.95.2.2 Action bridge(user/1001)
107. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/100201@10.95.2.2) State Change CS_ROUTING -> CS_EXECUTE
108. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100201@10.95.2.2) State ROUTING going to sleep
109. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_EXECUTE (Cur 1 Tot 25)
110. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/100201@10.95.2.2) State EXECUTE
111. 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:198 sofia/internal/100201@10.95.2.2 SOFIA EXECUTE
112. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:328 sofia/internal/100201@10.95.2.2 Standard EXECUTE
113. EXECUTE sofia/internal/100201@10.95.2.2 bridge(user/1001)
114. 2017-10-17 17:20:41.272585 [ALERT] switch_core_session.c:2799 sofia/internal/100201@10.95.2.2 receive message [APPLICATION_EXEC]
115. 2017-10-17 17:20:41.272585 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
116. 2017-10-17 17:20:41.272585 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
117. 2017-10-17 17:20:41.272585 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@10.95.2.81:50461 [dd008d70-5ef3-4627-9a5f-af27f10d512f]
118. 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:4819 (sofia/internal/1001@10.95.2.81:50461) State Change CS_NEW -> CS_INIT
119. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_INIT (Cur 2 Tot 26)
120. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@10.95.2.81:50461) State INIT
121. 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:90 sofia/internal/1001@10.95.2.81:50461 SOFIA INIT
122. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
123. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
124. 2017-10-17 17:20:41.272585 [DEBUG] sofia_glue.c:1295 sofia/internal/1001@10.95.2.81:50461 sending invite version: 1.6.17 git eb93b81 2017-05-08 21:44:33Z 64bit
125. Local SDP:
126. v=0
127. o=ECSCore 1508231095 1508231096 IN IP4 10.3.2.4
128. s=ECSCore
129. c=IN IP4 10.3.2.4
130. t=0 0
131. m=audio 26146 RTP/AVP 0 101
132. a=rtpmap:0 PCMU/8000
133. a=rtpmap:101 telephone-event/8000
134. a=fmtp:101 0-16
135. a=ptime:20
136. a=sendrecv
137.  
138. nua.c:633 nua_invite() nua: nua_invite: entering
139. nua_stack.c:569 nua_stack_signal() nua(0x7f0d98031830): recv signal r_invite
140. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
141. soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0d98031830) called
142. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017760, ...) called
143. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017760, ...) called
144. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f0da0017760, (nil), 0x7f0d9803426f, -1) called
145. soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f0da0017760, (nil), 0x7f0d9803426f, -1) called
146. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f0d98031830): adding session usage
147. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da001c9f0)
148. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f0da0017760) called
149. soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7f0da0017760, 0) called
150. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f0da0017760, soa_generate_offer): called
151. soa_static.c:1189 offer_answer_step() soa_static(0x7f0da0017760, soa_generate_offer): generating local description
152. soa_static.c:1217 offer_answer_step() soa_static(0x7f0da0017760, soa_generate_offer): upgrade with local description
153. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f0daededac0, (nil), ""): called
154. soa_static.c:1446 offer_answer_step() soa_static(0x7f0da0017760, soa_generate_offer): storing local description
155. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f0da0017760, [(nil)], [0x7f0daedefbf8], [0x7f0daedefbf4]) called
156. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
157. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.81:50461
158. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461
159. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.81:50461
160. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 1087 bytes of 1087 to udp/10.95.2.81:50461
161. tport.c:3492 tport_send_msg() tport_vsend returned 1087
162. send 1087 bytes to udp/[10.95.2.81]:50461 at 17:20:41.285391:
163.    ------------------------------------------------------------------------
164.    INVITE sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7 SIP/2.0
165.    Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bK9vy19Z6831rmB
166.    Max-Forwards: 69
167.    From: "100201" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
168.    To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
169.    Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
170.    CSeq: 113792556 INVITE
171.    Contact: <sip:mod_sofia@10.3.2.4:5060>
172.    User-Agent: ECSCore
173.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
174.    Supported: timer, path, replaces
175.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
176.    Content-Type: application/sdp
177.    Content-Disposition: session
178.    Content-Length: 206
179.    Remote-Party-ID: "100201" <sip:100201@10.3.2.4>;party=calling;screen=yes;privacy=off
180.  
181.    v=0
182.    o=ECSCore 1508231095 1508231096 IN IP4 10.3.2.4
183.    s=ECSCore
184.    c=IN IP4 10.3.2.4
185.    t=0 0
186.    m=audio 26146 RTP/AVP 0 101
187.    a=rtpmap:0 PCMU/8000
188.    a=rtpmap:101 telephone-event/8000
189.    a=fmtp:101 0-16
190.    a=ptime:20
191.    ------------------------------------------------------------------------
192. nta.c:8304 outgoing_send() nta: sent INVITE (113792556) to */10.95.2.81:50461
193. tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da0016d00 for udp/10.3.2.4:5060 (already 0)
194. nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: init -> calling, sent offer
195. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f0da0017760, [0x7f0daedefbd8], [0x7f0daedefbe0], [(nil)]) called
196. nua_stack.c:269 nua_stack_event() nua(0x7f0d98031830): event i_state INVITE sent
197. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
198. nua_stack.c:529 nua_signal() nua(0x7f0d98031830): sent signal r_invite
199. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@10.95.2.81:50461 Standard INIT
200. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@10.95.2.81:50461) State Change CS_INIT -> CS_ROUTING
201. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@10.95.2.81:50461) State INIT going to sleep
202. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_ROUTING (Cur 2 Tot 26)
203. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
204. 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@10.95.2.81:50461 entering state [calling][0]
205. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
206. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@10.95.2.81:50461) State ROUTING
207. 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:143 sofia/internal/1001@10.95.2.81:50461 SOFIA ROUTING
208. 2017-10-17 17:20:41.272585 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@10.95.2.81:50461) State Change CS_ROUTING -> CS_CONSUME_MEDIA
209. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@10.95.2.81:50461) State ROUTING going to sleep
210. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 26)
211. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@10.95.2.81:50461) State CONSUME_MEDIA
212. 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@10.95.2.81:50461) State CONSUME_MEDIA going to sleep
213. 2017-10-17 17:20:41.272585 [ALERT] switch_core_state_machine.c:701 sofia/internal/1001@10.95.2.81:50461 session thread sleep state: CS_CONSUME_MEDIA!
214. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
215. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
216. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0011bf0 from (udp/10.3.2.4:5060) has 294 bytes, veclen = 1
217. recv 294 bytes from udp/[10.95.2.81]:50461 at 17:20:41.370194:
218.    ------------------------------------------------------------------------
219.    SIP/2.0 100 Trying
220.    Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bK9vy19Z6831rmB
221.    To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
222.    From: "100201" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
223.    Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
224.    CSeq: 113792556 INVITE
225.    Content-Length: 0
226.  
227.    ------------------------------------------------------------------------
228. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0011bf0 (294 bytes) from udp/10.95.2.81:5060/sip next=(nil)
229. nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (113792556)
230. nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction
231. nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 84.931 ms
232. tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0016d00 by 0x7f0da0026140 with 0x7f0da0011bf0 (preliminary)
233. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
234. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
235. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0011bf0 from (udp/10.3.2.4:5060) has 445 bytes, veclen = 1
236. recv 445 bytes from udp/[10.95.2.81]:50461 at 17:20:41.420582:
237.    ------------------------------------------------------------------------
238.    SIP/2.0 180 Ringing
239.    Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bK9vy19Z6831rmB
240.    Contact: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
241.    To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
242.    From: "100201" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
243.    Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
244.    CSeq: 113792556 INVITE
245.    User-Agent: Bria 4 release 4.8.2 stamp 85656
246.    Allow-Events: talk, hold
247.    Content-Length: 0
248.  
249.    ------------------------------------------------------------------------
250. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0011bf0 (445 bytes) from udp/10.95.2.81:5060/sip next=(nil)
251. nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (113792556)
252. nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction
253. tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0016d00 by 0x7f0da0026140 with 0x7f0da0011bf0 (preliminary)
254. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event r_invite 180 Ringing
255. nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: calling -> proceeding
256. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_state 180 Ringing
257. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
258. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
259. 2017-10-17 17:20:41.412599 [ALERT] switch_core_state_machine.c:705 sofia/internal/1001@10.95.2.81:50461 session thread wake state: CS_CONSUME_MEDIA!
260. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
261. 2017-10-17 17:20:41.412599 [ALERT] sofia.c:1274 sofia/internal/1001@10.95.2.81:50461 Same Callee ID "Outbound Call" <1001>
262. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
263. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
264. 2017-10-17 17:20:41.412599 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@10.95.2.81:50461 entering state [proceeding][180]
265. 2017-10-17 17:20:41.412599 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/1001@10.95.2.81:50461!
266. 2017-10-17 17:20:41.412599 [DEBUG] switch_channel.c:3345 (sofia/internal/1001@10.95.2.81:50461) Callstate Change DOWN -> RINGING
267. 2017-10-17 17:20:41.412599 [ALERT] sofia.c:7156 sofia/internal/1001@10.95.2.81:50461 receive message [RING_EVENT]
268. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
269. 2017-10-17 17:20:41.412599 [ALERT] switch_core_state_machine.c:701 sofia/internal/1001@10.95.2.81:50461 session thread sleep state: CS_CONSUME_MEDIA!
270. 2017-10-17 17:20:41.412599 [ALERT] switch_ivr_originate.c:525 sofia/internal/100201@10.95.2.2 receive message [RINGING]
271. nua.c:879 nua_respond() nua: nua_respond: entering
272. nua_stack.c:573 nua_stack_signal() nua(0x7f0da00130b0): recv signal r_respond 180 Ringing
273. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
274. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017b10, ...) called
275. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
276. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
277. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
278. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
279. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 652 bytes of 652 to udp/10.95.2.2:5060
280. tport.c:3492 tport_send_msg() tport_vsend returned 652
281. send 652 bytes to udp/[10.95.2.2]:5060 at 17:20:41.430051:
282.    ------------------------------------------------------------------------
283.    SIP/2.0 180 Ringing
284.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
285.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
286.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
287.    Call-ID: 100201@10.95.2.2:5060
288.    CSeq: 13 INVITE
289.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
290.    User-Agent: ECSCore
291.    Accept: application/sdp
292.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
293.    Supported: timer, path, replaces
294.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
295.    Content-Length: 0
296.  
297.    ------------------------------------------------------------------------
298. nta.c:6791 incoming_reply() nta: sent 180 Ringing for INVITE (13)
299. nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: received -> early
300. nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_state 180 Ringing
301. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
302. nua_stack.c:529 nua_signal() nua(0x7f0da00130b0): sent signal r_respond
303. 2017-10-17 17:20:41.412599 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/internal/100201@10.95.2.2!
304. 2017-10-17 17:20:41.412599 [ALERT] mod_sofia.c:2273 sofia/internal/100201@10.95.2.2 receive message [RING_EVENT]
305. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
306. 2017-10-17 17:20:41.412599 [DEBUG] sofia.c:7048 Channel sofia/internal/100201@10.95.2.2 entering state [early][180]
307. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
308. 2017-10-17 17:20:41.412599 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/internal/100201@10.95.2.2!
309. nta.c:1296 agent_timer() nta: timer set next to 450 ms
310. nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response
311. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f0daedefc60)
312. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/3 free
313. nta.c:1296 agent_timer() nta: timer set next to 30852 ms
314. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
315. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
316. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0010400 from (udp/10.3.2.4:5060) has 4 bytes, veclen = 1
317. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): bad msg 0x7f0da0010400 (4 bytes) from udp/10.95.2.81:5060/sip next=(nil)
318. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
319. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
320. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0010400 from (udp/10.3.2.4:5060) has 749 bytes, veclen = 1
321. recv 749 bytes from udp/[10.95.2.81]:50461 at 17:20:45.955214:
322.    ------------------------------------------------------------------------
323.    SIP/2.0 200 OK
324.    Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bK9vy19Z6831rmB
325.    Contact: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
326.    To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
327.    From: "100201" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
328.    Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
329.    CSeq: 113792556 INVITE
330.    Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, MESSAGE
331.    Content-Type: application/sdp
332.    Supported: replaces
333.    User-Agent: Bria 4 release 4.8.2 stamp 85656
334.    Content-Length: 198
335.  
336.    v=0
337.    o=- 2169747360 3 IN IP4 10.95.2.81
338.    s=Bria 4 release 4.8.2 stamp 85656
339.    c=IN IP4 10.95.2.81
340.    t=0 0
341.    m=audio 58876 RTP/AVP 0 101
342.    a=rtpmap:101 telephone-event/8000
343.    a=fmtp:101 0-15
344.    a=sendrecv
345.    ------------------------------------------------------------------------
346. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0010400 (749 bytes) from udp/10.95.2.81:5060/sip next=(nil)
347. nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (113792556)
348. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
349. tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0016d00 by 0x7f0da0026140 with 0x7f0da0010400
350. soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f0da0017760, (nil), 0x7f0da0014247, 198) called
351. soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f0da0017760) called
352. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f0da0017760, soa_process_answer): called
353. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f0da0023340, 0x7f0da0013350, ""): called
354. soa_static.c:1304 offer_answer_step() soa_static(0x7f0da0017760, soa_process_answer): upgrade codecs with remote description
355. soa.c:1730 soa_activate() soa_activate(static::0x7f0da0017760, (nil)) called
356. nua_session.c:988 nua_session_client_response() nua(0x7f0d98031830): INVITE: processed SDP answer in 200 OK
357. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event r_invite 200 OK
358. nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: proceeding -> completing, received answer
359. soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f0da0017760, [0x7f0daedef648], [0x7f0daedef650], [(nil)]) called
360. soa.c:616 soa_get_params() soa_get_params(static::0x7f0da0017760, ...) called
361. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_state 200 OK
362. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
363. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
364. 2017-10-17 17:20:45.952567 [ALERT] switch_core_state_machine.c:705 sofia/internal/1001@10.95.2.81:50461 session thread wake state: CS_CONSUME_MEDIA!
365. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
366. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:447 Looking for zrtp-hash
367. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:402 Deciding whether to pass zrtp-hash between legs
368. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:410 Found peer channel; propagating zrtp-hash if set
369. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg
370. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg
371. 2017-10-17 17:20:45.952567 [ALERT] sofia.c:1274 sofia/internal/1001@10.95.2.81:50461 Same Callee ID "Outbound Call" <1001>
372. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
373. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
374. 2017-10-17 17:20:45.952567 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@10.95.2.81:50461 entering state [completing][200]
375. 2017-10-17 17:20:45.952567 [DEBUG] sofia.c:7058 Remote SDP:
376. v=0
377. o=- 2169747360 3 IN IP4 10.95.2.81
378. s=Bria 4 release 4.8.2 stamp 85656
379. c=IN IP4 10.95.2.81
380. t=0 0
381. m=audio 58876 RTP/AVP 0 101
382. a=rtpmap:101 telephone-event/8000
383. a=fmtp:101 0-15
384.  
385. nua.c:639 nua_ack() nua: nua_ack: entering
386. nua_stack.c:569 nua_stack_signal() nua(0x7f0d98031830): recv signal r_ack
387. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
388. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017760, ...) called
389. soa.c:1730 soa_activate() soa_activate(static::0x7f0da0017760, (nil)) called
390. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
391. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.81:50461
392. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461
393. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.81:50461
394. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 403 bytes of 403 to udp/10.95.2.81:50461
395. tport.c:3492 tport_send_msg() tport_vsend returned 403
396. send 403 bytes to udp/[10.95.2.81]:50461 at 17:20:45.956375:
397.    ------------------------------------------------------------------------
398.    ACK sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7 SIP/2.0
399.    Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKa6QtBUQc1aF7p
400.    Max-Forwards: 70
401.    From: "100201" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
402.    To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
403.    Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
404.    CSeq: 113792556 ACK
405.    Contact: <sip:mod_sofia@10.3.2.4:5060>
406.    Content-Length: 0
407.  
408.    ------------------------------------------------------------------------
409. nta.c:8304 outgoing_send() nta: sent ACK (113792556) to */10.95.2.81:50461
410. nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: completing -> ready
411. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_state 200 ACK sent
412. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_active 200 Call active
413. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
414. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
415. nua_stack.c:529 nua_signal() nua(0x7f0d98031830): sent signal r_ack
416. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
417. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
418. 2017-10-17 17:20:45.952567 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@10.95.2.81:50461 entering state [ready][200]
419. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:447 Looking for zrtp-hash
420. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:402 Deciding whether to pass zrtp-hash between legs
421. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:410 Found peer channel; propagating zrtp-hash if set
422. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg
423. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg
424. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
425. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
426. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
427. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/1001@10.95.2.81:50461 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
428. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@10.95.2.81:50461 Original read codec set to PCMU:0
429. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
430. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4754 sofia/internal/1001@10.95.2.81:50461 Set 2833 dtmf send payload to 101 recv payload to 101
431. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/1001@10.95.2.81:50461] 10.3.2.4 port 26146 -> 10.95.2.81 port 58876 codec: 0 ms: 20
432. 2017-10-17 17:20:45.952567 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms
433. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7166 sofia/internal/1001@10.95.2.81:50461 Set 2833 dtmf send payload to 101
434. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7173 sofia/internal/1001@10.95.2.81:50461 Set 2833 dtmf receive payload to 101
435. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7196 sofia/internal/1001@10.95.2.81:50461 Set rtp dtmf delay to 40
436. 2017-10-17 17:20:45.952567 [NOTICE] sofia.c:8182 Channel [sofia/internal/1001@10.95.2.81:50461] has been answered
437. 2017-10-17 17:20:45.952567 [DEBUG] switch_channel.c:3772 (sofia/internal/1001@10.95.2.81:50461) Callstate Change RINGING -> ACTIVE
438. 2017-10-17 17:20:45.952567 [ALERT] sofia.c:8182 sofia/internal/1001@10.95.2.81:50461 receive message [ANSWER_EVENT]
439. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
440. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
441. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
442. 2017-10-17 17:20:45.952567 [ALERT] switch_core_state_machine.c:701 sofia/internal/1001@10.95.2.81:50461 session thread sleep state: CS_CONSUME_MEDIA!
443. 2017-10-17 17:20:45.952567 [ALERT] switch_ivr_originate.c:3632 sofia/internal/100201@10.95.2.2 receive message [ANSWER]
444. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:447 Looking for zrtp-hash
445. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:402 Deciding whether to pass zrtp-hash between legs
446. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:410 Found peer channel; propagating zrtp-hash if set
447. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg
448. 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg
449. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
450. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
451. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/100201@10.95.2.2 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
452. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_codec.c:111 sofia/internal/100201@10.95.2.2 Original read codec set to PCMU:0
453. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4725 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
454. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4754 sofia/internal/100201@10.95.2.2 Set 2833 dtmf send payload to 101 recv payload to 101
455. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/100201@10.95.2.2] 10.3.2.4 port 18162 -> 10.95.2.2 port 7068 codec: 0 ms: 20
456. 2017-10-17 17:20:45.952567 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms
457. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7166 sofia/internal/100201@10.95.2.2 Set 2833 dtmf send payload to 101
458. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7173 sofia/internal/100201@10.95.2.2 Set 2833 dtmf receive payload to 101
459. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7196 sofia/internal/100201@10.95.2.2 Set rtp dtmf delay to 40
460. 2017-10-17 17:20:45.952567 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/100201@10.95.2.2!
461. 2017-10-17 17:20:45.972802 [DEBUG] switch_channel.c:3473 (sofia/internal/100201@10.95.2.2) Callstate Change RINGING -> EARLY
462. 2017-10-17 17:20:45.972802 [ALERT] sofia_media.c:92 sofia/internal/100201@10.95.2.2 receive message [PROGRESS_EVENT]
463. 2017-10-17 17:20:45.972802 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/100201@10.95.2.2.
464. 2017-10-17 17:20:45.972802 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/100201@10.95.2.2:
465. v=0
466. o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
467. s=ECSCore
468. c=IN IP4 10.3.2.4
469. t=0 0
470. m=audio 18162 RTP/AVP 0 101
471. a=rtpmap:0 PCMU/8000
472. a=rtpmap:101 telephone-event/8000
473. a=fmtp:101 0-16
474. a=ptime:20
475. a=sendrecv
476.  
477. nua.c:879 nua_respond() nua: nua_respond: entering
478. nua_stack.c:573 nua_stack_signal() nua(0x7f0da00130b0): recv signal r_respond 200 OK
479. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
480. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017b10, ...) called
481. soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f0da0017b10, (nil), 0x7f0da401c658, -1) called
482. soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f0da0017b10, (nil), 0x7f0da401c658, -1) called
483. nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
484. soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7f0da0017b10) called
485. soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f0da0017b10, soa_generate_answer): called
486. soa_static.c:1189 offer_answer_step() soa_static(0x7f0da0017b10, soa_generate_answer): generating local description
487. soa_static.c:1230 offer_answer_step() soa_static(0x7f0da0017b10, soa_generate_answer): upgrade with remote description
488. soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f0daededb00, 0x7f0da00262b0, ""): called
489. soa_static.c:1446 offer_answer_step() soa_static(0x7f0da0017b10, soa_generate_answer): storing local description
490. soa.c:1730 soa_activate() soa_activate(static::0x7f0da0017b10, (nil)) called
491. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f0da0017b10, [(nil)], [0x7f0daedefc38], [0x7f0daedefc34]) called
492. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
493. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
494. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
495. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
496. tport.c:3492 tport_send_msg() tport_vsend returned 891
497. send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:45.973386:
498.    ------------------------------------------------------------------------
499.    SIP/2.0 200 OK
500.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
501.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
502.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
503.    Call-ID: 100201@10.95.2.2:5060
504.    CSeq: 13 INVITE
505.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
506.    User-Agent: ECSCore
507.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
508.    Supported: timer, path, replaces
509.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
510.    Content-Type: application/sdp
511.    Content-Disposition: session
512.    Content-Length: 206
513.  
514.    v=0
515.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
516.    s=ECSCore
517.    c=IN IP4 10.3.2.4
518.    t=0 0
519.    m=audio 18162 RTP/AVP 0 101
520.    a=rtpmap:0 PCMU/8000
521.    a=rtpmap:101 telephone-event/8000
522.    a=fmtp:101 0-16
523.    a=ptime:20
524.    ------------------------------------------------------------------------
525. nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (13)
526. nta.c:1348 set_timeout() nta: timer shortened to 500 ms
527. nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: early -> completed, sent answer
528. soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f0da0017b10, [0x7f0daedefce8], [0x7f0daedefcf0], [(nil)]) called
529. soa.c:616 soa_get_params() soa_get_params(static::0x7f0da0017b10, ...) called
530. nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_state 200 OK
531. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
532. nua_stack.c:529 nua_signal() nua(0x7f0da00130b0): sent signal r_respond
533. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
534. 2017-10-17 17:20:45.972802 [DEBUG] sofia.c:7048 Channel sofia/internal/100201@10.95.2.2 entering state [completed][200]
535. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
536. 2017-10-17 17:20:45.972802 [NOTICE] switch_ivr_originate.c:3632 Channel [sofia/internal/100201@10.95.2.2] has been answered
537. 2017-10-17 17:20:45.972802 [DEBUG] switch_channel.c:3772 (sofia/internal/100201@10.95.2.2) Callstate Change EARLY -> ACTIVE
538. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:3632 sofia/internal/100201@10.95.2.2 receive message [ANSWER_EVENT]
539. 2017-10-17 17:20:45.972802 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1001@10.95.2.81:50461]
540. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:4026 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC]
541. 2017-10-17 17:20:45.972802 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1001@10.95.2.81:50461]
542. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:4026 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC]
543. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:4023 sofia/internal/1001@10.95.2.81:50461 receive message [AUDIO_SYNC]
544. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:4023 sofia/internal/1001@10.95.2.81:50461 receive message [AUDIO_SYNC]
545. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_bridge.c:1462 sofia/internal/1001@10.95.2.81:50461 receive message [AUDIO_SYNC]
546. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr.c:217 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC]
547. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_bridge.c:1461 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC]
548. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_bridge.c:1561 sofia/internal/1001@10.95.2.81:50461 receive message [BRIDGE]
549. 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_bridge.c:1569 sofia/internal/100201@10.95.2.2 receive message [BRIDGE]
550. 2017-10-17 17:20:45.972802 [DEBUG] switch_ivr_bridge.c:1601 (sofia/internal/1001@10.95.2.81:50461) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
551. 2017-10-17 17:20:45.972802 [ALERT] switch_core_state_machine.c:705 sofia/internal/1001@10.95.2.81:50461 session thread wake state: CS_CONSUME_MEDIA!
552. 2017-10-17 17:20:45.972802 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 26)
553. 2017-10-17 17:20:45.972802 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1001@10.95.2.81:50461) State EXCHANGE_MEDIA
554. 2017-10-17 17:20:45.972802 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
555. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
556. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
557. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0012d00 from (udp/10.3.2.4:5060) has 326 bytes, veclen = 1
558. recv 326 bytes from udp/[10.95.2.2]:5060 at 17:20:45.977755:
559.    ------------------------------------------------------------------------
560.    ACK sip:30161@10.3.2.4:5060 SIP/2.0
561.    Contact: <sip:100201@10.95.2.2:5060>
562.    User-Agent: TATTILE PBX v.3.4
563.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
564.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
565.    Call-ID: 100201@10.95.2.2:5060
566.    CSeq: 13 INVITE
567.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
568.    Content-Length: 0
569.  
570.    ------------------------------------------------------------------------
571. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0012d00 (326 bytes) from udp/10.95.2.2:5060/sip next=(nil)
572. nta.c:2880 agent_recv_request() nta: received ACK sip:30161@10.3.2.4:5060 SIP/2.0 (CSeq 13)
573. nta.c:2931 agent_recv_request() nta: ACK (13) failed sanity check
574. 2017-10-17 17:20:46.032697 [DEBUG] switch_rtp.c:7231 Correct audio ip/port confirmed.
575. 2017-10-17 17:20:46.212568 [DEBUG] switch_rtp.c:7231 Correct audio ip/port confirmed.
576. 2017-10-17 17:20:46.352697 [WARNING] switch_core_media.c:2475 [CBR]: Asynchronous PTIME not supported, changing our end from 20 to 10
577. 2017-10-17 17:20:46.372602 [DEBUG] switch_core_media.c:2954 Changing Codec from PCMU@20ms@8000hz to PCMU@10ms@8000hz
578. 2017-10-17 17:20:46.412568 [DEBUG] switch_rtp.c:3974 RE-Starting timer [soft] 80 bytes per 10ms
579. 2017-10-17 17:20:46.412568 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/100201@10.95.2.2 PCMU/8000 10 ms 80 samples 64000 bits 1 channels
580. 2017-10-17 17:20:46.412568 [DEBUG] switch_core_codec.c:123 sofia/internal/100201@10.95.2.2 Original read codec replaced with PCMU:0
581. 2017-10-17 17:20:46.412568 [ALERT] switch_core_media.c:2952 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC]
582. 2017-10-17 17:20:46.412568 [ALERT] switch_core_media.c:2971 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC]
583. 2017-10-17 17:20:46.412568 [ALERT] switch_core_media.c:3017 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC]
584. 2017-10-17 17:20:46.432785 [ALERT] switch_core_io.c:1152 sofia/internal/100201@10.95.2.2 receive message [TRANSCODING_NECESSARY]
585. 2017-10-17 17:20:46.432785 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 160 bytes to accommodate 320->160
586. 2017-10-17 17:20:46.432785 [ALERT] switch_rtp.c:6827 sofia/internal/100201@10.95.2.2 syncing 1 audio packet(s)
587. 2017-10-17 17:20:46.432785 [ALERT] switch_core_io.c:1152 sofia/internal/1001@10.95.2.81:50461 receive message [TRANSCODING_NECESSARY]
588. 2017-10-17 17:20:46.432785 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 320 bytes to accommodate 160->320
589. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
590. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
591. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
592. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
593. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
594. tport.c:3492 tport_send_msg() tport_vsend returned 891
595. send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:46.474198:
596.    ------------------------------------------------------------------------
597.    SIP/2.0 200 OK
598.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
599.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
600.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
601.    Call-ID: 100201@10.95.2.2:5060
602.    CSeq: 13 INVITE
603.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
604.    User-Agent: ECSCore
605.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
606.    Supported: timer, path, replaces
607.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
608.    Content-Type: application/sdp
609.    Content-Disposition: session
610.    Content-Length: 206
611.  
612.    v=0
613.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
614.    s=ECSCore
615.    c=IN IP4 10.3.2.4
616.    t=0 0
617.    m=audio 18162 RTP/AVP 0 101
618.    a=rtpmap:0 PCMU/8000
619.    a=rtpmap:101 telephone-event/8000
620.    a=fmtp:101 0-16
621.    a=ptime:20
622.    ------------------------------------------------------------------------
623. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
624. nta.c:1296 agent_timer() nta: timer set next to 1000 ms
625. 2017-10-17 17:20:46.532568 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 0.00 0/1 flaws: 1 mos: 1.00 v: 0.00 0.00/0.00
626. 2017-10-17 17:20:46.532568 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 10.000000
627. 2017-10-17 17:20:46.554525 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 3.500000
628. 2017-10-17 17:20:46.554525 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 1.005263
629. 2017-10-17 17:20:46.554525 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 2.100000
630. 2017-10-17 17:20:46.554525 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 1.400000
631. 2017-10-17 17:20:46.592597 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 1.428571
632. 2017-10-17 17:20:46.612567 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 1.111111
633. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
634. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
635. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
636. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
637. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
638. tport.c:3492 tport_send_msg() tport_vsend returned 891
639. send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:47.474915:
640.    ------------------------------------------------------------------------
641.    SIP/2.0 200 OK
642.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
643.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
644.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
645.    Call-ID: 100201@10.95.2.2:5060
646.    CSeq: 13 INVITE
647.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
648.    User-Agent: ECSCore
649.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
650.    Supported: timer, path, replaces
651.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
652.    Content-Type: application/sdp
653.    Content-Disposition: session
654.    Content-Length: 206
655.  
656.    v=0
657.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
658.    s=ECSCore
659.    c=IN IP4 10.3.2.4
660.    t=0 0
661.    m=audio 18162 RTP/AVP 0 101
662.    a=rtpmap:0 PCMU/8000
663.    a=rtpmap:101 telephone-event/8000
664.    a=fmtp:101 0-16
665.    a=ptime:20
666.    ------------------------------------------------------------------------
667. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
668. nta.c:1296 agent_timer() nta: timer set next to 2000 ms
669. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
670. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
671. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
672. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
673. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
674. tport.c:3492 tport_send_msg() tport_vsend returned 891
675. send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:49.475385:
676.    ------------------------------------------------------------------------
677.    SIP/2.0 200 OK
678.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
679.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
680.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
681.    Call-ID: 100201@10.95.2.2:5060
682.    CSeq: 13 INVITE
683.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
684.    User-Agent: ECSCore
685.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
686.    Supported: timer, path, replaces
687.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
688.    Content-Type: application/sdp
689.    Content-Disposition: session
690.    Content-Length: 206
691.  
692.    v=0
693.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
694.    s=ECSCore
695.    c=IN IP4 10.3.2.4
696.    t=0 0
697.    m=audio 18162 RTP/AVP 0 101
698.    a=rtpmap:0 PCMU/8000
699.    a=rtpmap:101 telephone-event/8000
700.    a=fmtp:101 0-16
701.    a=ptime:20
702.    ------------------------------------------------------------------------
703. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
704. nta.c:1296 agent_timer() nta: timer set next to 4001 ms
705. 2017-10-17 17:20:51.552576 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 502/503 flaws: 1 mos: 4.49 v: 127.75 105.55/266.43
706. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
707. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
708. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
709. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
710. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
711. tport.c:3492 tport_send_msg() tport_vsend returned 891
712. send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:53.477339:
713.    ------------------------------------------------------------------------
714.    SIP/2.0 200 OK
715.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
716.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
717.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
718.    Call-ID: 100201@10.95.2.2:5060
719.    CSeq: 13 INVITE
720.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
721.    User-Agent: ECSCore
722.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
723.    Supported: timer, path, replaces
724.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
725.    Content-Type: application/sdp
726.    Content-Disposition: session
727.    Content-Length: 206
728.  
729.    v=0
730.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
731.    s=ECSCore
732.    c=IN IP4 10.3.2.4
733.    t=0 0
734.    m=audio 18162 RTP/AVP 0 101
735.    a=rtpmap:0 PCMU/8000
736.    a=rtpmap:101 telephone-event/8000
737.    a=fmtp:101 0-16
738.    a=ptime:20
739.    ------------------------------------------------------------------------
740. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
741. nta.c:1296 agent_timer() nta: timer set next to 4001 ms
742. 2017-10-17 17:20:56.572599 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 1004/1005 flaws: 1 mos: 4.49 v: 123.71 105.55/266.43
743. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
744. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
745. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
746. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
747. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
748. tport.c:3492 tport_send_msg() tport_vsend returned 891
749. send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:57.478830:
750.    ------------------------------------------------------------------------
751.    SIP/2.0 200 OK
752.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
753.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
754.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
755.    Call-ID: 100201@10.95.2.2:5060
756.    CSeq: 13 INVITE
757.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
758.    User-Agent: ECSCore
759.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
760.    Supported: timer, path, replaces
761.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
762.    Content-Type: application/sdp
763.    Content-Disposition: session
764.    Content-Length: 206
765.  
766.    v=0
767.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
768.    s=ECSCore
769.    c=IN IP4 10.3.2.4
770.    t=0 0
771.    m=audio 18162 RTP/AVP 0 101
772.    a=rtpmap:0 PCMU/8000
773.    a=rtpmap:101 telephone-event/8000
774.    a=fmtp:101 0-16
775.    a=ptime:20
776.    ------------------------------------------------------------------------
777. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
778. nta.c:1296 agent_timer() nta: timer set next to 4000 ms
779. 2017-10-17 17:21:00.452655 [ALERT] sofia_reg.c:939 Updating ping expires for profile internal
780. 2017-10-17 17:21:00.452655 [ALERT] sofia_reg.c:875 Generated random 16, max is 30
781. 2017-10-17 17:21:01.452603 [NOTICE] sofia_reg.c:448 Registering ale
782. nua.c:622 nua_register() nua: nua_register: entering
783. nua_stack.c:569 nua_stack_signal() nua(0x7f0d9c030d40): recv signal r_register
784. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
785. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da000f2b0, ...) called
786. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f0d9c030d40): adding register usage
787. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da0018140)
788. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
789. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = udp/192.168.1.11:5060
790. tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.1.11:5060
791. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name udp/192.168.1.11:5060
792. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 536 bytes of 536 to udp/192.168.1.11:5060
793. tport.c:3492 tport_send_msg() tport_vsend returned 536
794. send 536 bytes to udp/[192.168.1.11]:5060 at 17:21:01.458539:
795.    ------------------------------------------------------------------------
796.    REGISTER sip:192.168.1.11;transport=udp SIP/2.0
797.    Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKBFHKDp8FyK5Sj
798.    Max-Forwards: 70
799.    From: <sip:ale@192.168.1.11>;tag=7v3HXmaU70B4r
800.    To: <sip:ale@192.168.1.11>
801.    Call-ID: 3bf2563f-444c-4541-9dc9-9b73f46b2ea2
802.    CSeq: 113792566 REGISTER
803.    Contact: <sip:gw+ale@10.3.2.4:5060;transport=udp;gw=ale>
804.    Expires: 3600
805.    User-Agent: ECSCore
806.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
807.    Supported: timer, path, replaces
808.    Content-Length: 0
809.  
810.    ------------------------------------------------------------------------
811. nta.c:8304 outgoing_send() nta: sent REGISTER (113792566) to udp/192.168.1.11:5060
812. tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da001a580 for udp/10.3.2.4:5060 (already 0)
813. nua_stack.c:529 nua_signal() nua(0x7f0d9c030d40): sent signal r_register
814. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
815. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
816. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
817. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
818. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
819. tport.c:3492 tport_send_msg() tport_vsend returned 891
820. send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:01.478804:
821.    ------------------------------------------------------------------------
822.    SIP/2.0 200 OK
823.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
824.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
825.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
826.    Call-ID: 100201@10.95.2.2:5060
827.    CSeq: 13 INVITE
828.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
829.    User-Agent: ECSCore
830.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
831.    Supported: timer, path, replaces
832.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
833.    Content-Type: application/sdp
834.    Content-Disposition: session
835.    Content-Length: 206
836.  
837.    v=0
838.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
839.    s=ECSCore
840.    c=IN IP4 10.3.2.4
841.    t=0 0
842.    m=audio 18162 RTP/AVP 0 101
843.    a=rtpmap:0 PCMU/8000
844.    a=rtpmap:101 telephone-event/8000
845.    a=fmtp:101 0-16
846.    a=ptime:20
847.    ------------------------------------------------------------------------
848. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
849. nta.c:1296 agent_timer() nta: timer set next to 980 ms
850. 2017-10-17 17:21:01.592574 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 1506/1507 flaws: 1 mos: 4.49 v: 118.89 105.55/266.43
851. nta.c:8893 _nta_outgoing_timer() nta: timer E fired, retransmit REGISTER (113792566)
852. tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da001a580 by 0x7f0da00165c0 with (nil)
853. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = udp/192.168.1.11:5060
854. tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.1.11:5060
855. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name udp/192.168.1.11:5060
856. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 536 bytes of 536 to udp/192.168.1.11:5060
857. tport.c:3492 tport_send_msg() tport_vsend returned 536
858. send 536 bytes to udp/[192.168.1.11]:5060 at 17:21:02.460134:
859.    ------------------------------------------------------------------------
860.    REGISTER sip:192.168.1.11;transport=udp SIP/2.0
861.    Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKBFHKDp8FyK5Sj
862.    Max-Forwards: 70
863.    From: <sip:ale@192.168.1.11>;tag=7v3HXmaU70B4r
864.    To: <sip:ale@192.168.1.11>
865.    Call-ID: 3bf2563f-444c-4541-9dc9-9b73f46b2ea2
866.    CSeq: 113792566 REGISTER
867.    Contact: <sip:gw+ale@10.3.2.4:5060;transport=udp;gw=ale>
868.    Expires: 3600
869.    User-Agent: ECSCore
870.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
871.    Supported: timer, path, replaces
872.    Content-Length: 0
873.  
874.    ------------------------------------------------------------------------
875. nta.c:8304 outgoing_send() nta: resent REGISTER (113792566) to udp/192.168.1.11:5060
876. tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da001a580 for udp/10.3.2.4:5060 (already 0)
877. nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/1 term, 0/3 free
878. nta.c:1296 agent_timer() nta: timer set next to 2000 ms
879. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events ERR
880. tport_type_udp.c:519 tport_udp_error() tport_udp_error: No route to host (113) [icmp type=3 code=1]
881. tport_type_udp.c:524 tport_udp_error()  reported by [10.3.2.4]:0
882. tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da001a580 by 0x7f0da00165c0 with (nil)
883. nta.c:8496 outgoing_print_tport_error() nta: REGISTER (113792566): No route to host (113) with udp/[192.168.1.11]:5060
884. nua_stack.c:271 nua_stack_event() nua(0x7f0d9c030d40): event r_register 503 Service Unavailable
885. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f0d9c030d40): removing register usage
886. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da0018140)
887. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events ERR
888. tport_type_udp.c:519 tport_udp_error() tport_udp_error: No route to host (113) [icmp type=3 code=1]
889. tport_type_udp.c:524 tport_udp_error()  reported by [10.3.2.4]:0
890. nta.c:2719 agent_tp_error() nta_agent: tport: 192.168.1.11:5060: No route to host
891. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
892. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
893. 2017-10-17 17:21:04.452578 [ERR] sofia_reg.c:2447 ale Failed Registration with status Service Unavailable [503]. failure #34
894. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
895. nta.c:1296 agent_timer() nta: timer set next to 1019 ms
896. 2017-10-17 17:21:04.452578 [WARNING] sofia_reg.c:505 ale Failed Registration [503], setting retry to 30 seconds.
897. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
898. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
899. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
900. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
901. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
902. tport.c:3492 tport_send_msg() tport_vsend returned 891
903. send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:05.480390:
904.    ------------------------------------------------------------------------
905.    SIP/2.0 200 OK
906.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
907.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
908.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
909.    Call-ID: 100201@10.95.2.2:5060
910.    CSeq: 13 INVITE
911.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
912.    User-Agent: ECSCore
913.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
914.    Supported: timer, path, replaces
915.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
916.    Content-Type: application/sdp
917.    Content-Disposition: session
918.    Content-Length: 206
919.  
920.    v=0
921.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
922.    s=ECSCore
923.    c=IN IP4 10.3.2.4
924.    t=0 0
925.    m=audio 18162 RTP/AVP 0 101
926.    a=rtpmap:0 PCMU/8000
927.    a=rtpmap:101 telephone-event/8000
928.    a=fmtp:101 0-16
929.    a=ptime:20
930.    ------------------------------------------------------------------------
931. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
932. nta.c:1296 agent_timer() nta: timer set next to 3975 ms
933. 2017-10-17 17:21:06.612763 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 2008/2009 flaws: 1 mos: 4.49 v: 116.82 105.55/266.43
934. nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate REGISTER (113792566)
935. nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f0daedefd40)
936. nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
937. nta.c:1296 agent_timer() nta: timer set next to 24 ms
938. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
939. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
940. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
941. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
942. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
943. tport.c:3492 tport_send_msg() tport_vsend returned 891
944. send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:09.480948:
945.    ------------------------------------------------------------------------
946.    SIP/2.0 200 OK
947.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
948.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
949.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
950.    Call-ID: 100201@10.95.2.2:5060
951.    CSeq: 13 INVITE
952.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
953.    User-Agent: ECSCore
954.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
955.    Supported: timer, path, replaces
956.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
957.    Content-Type: application/sdp
958.    Content-Disposition: session
959.    Content-Length: 206
960.  
961.    v=0
962.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
963.    s=ECSCore
964.    c=IN IP4 10.3.2.4
965.    t=0 0
966.    m=audio 18162 RTP/AVP 0 101
967.    a=rtpmap:0 PCMU/8000
968.    a=rtpmap:101 telephone-event/8000
969.    a=fmtp:101 0-16
970.    a=ptime:20
971.    ------------------------------------------------------------------------
972. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
973. nta.c:1296 agent_timer() nta: timer set next to 3302 ms
974. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
975. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
976. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0012d00 from (udp/10.3.2.4:5060) has 284 bytes, veclen = 1
977. recv 284 bytes from udp/[10.95.2.2]:5060 at 17:21:11.633254:
978.    ------------------------------------------------------------------------
979.    OPTIONS sip:10.3.2.4 SIP/2.0
980.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1034276
981.    Max-Forwards: 70
982.    From: <sip:10.95.2.2>;tag=123448
983.    To: <sip:10.3.2.4>
984.    Contact: <sip:10.95.2.2:5060>
985.    Call-ID: 10.95.2.2:5060
986.    CSeq: 34 OPTIONS
987.    User-Agent: TATTILE PBX v.3.4
988.    Content-Length: 0
989.  
990.    ------------------------------------------------------------------------
991. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0012d00 (284 bytes) from udp/10.95.2.2:5060/sip next=(nil)
992. nta.c:2880 agent_recv_request() nta: received OPTIONS sip:10.3.2.4 SIP/2.0 (CSeq 34)
993. nta.c:3248 agent_aliases() nta: canonizing sip:10.3.2.4 with contact
994. nta.c:3085 agent_recv_request() nta: OPTIONS (34) going to a default leg
995. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
996. nua_stack.c:899 nh_create() nua: nh_create: entering
997. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
998. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
999. soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0da0017360) called
1000. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da001e880, ...) called
1001. nua_stack.c:271 nua_stack_event() nua(0x7f0da0017360): event i_options 100 Trying
1002. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1003. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1004. nua.c:879 nua_respond() nua: nua_respond: entering
1005. nua_stack.c:573 nua_stack_signal() nua(0x7f0da0017360): recv signal r_respond 200 OK
1006. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
1007. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da001e880, ...) called
1008. soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0x7f0da001e880, [(nil)], [0x7f0daedefc68], [0x7f0daedefc64]) called
1009. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
1010. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
1011. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
1012. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 594 bytes of 594 to udp/10.95.2.2:5060
1013. tport.c:3492 tport_send_msg() tport_vsend returned 594
1014. send 594 bytes to udp/[10.95.2.2]:5060 at 17:21:11.633676:
1015.    ------------------------------------------------------------------------
1016.    SIP/2.0 200 OK
1017.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1034276
1018.    From: <sip:10.95.2.2>;tag=123448
1019.    To: <sip:10.3.2.4>;tag=9ep30ac21jr9F
1020.    Call-ID: 10.95.2.2:5060
1021.    CSeq: 34 OPTIONS
1022.    Contact: <sip:10.3.2.4>
1023.    User-Agent: ECSCore
1024.    Accept: application/sdp
1025.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1026.    Supported: timer, path, replaces
1027.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1028.    Content-Length: 0
1029.  
1030.    ------------------------------------------------------------------------
1031. nta.c:6791 incoming_reply() nta: sent 200 OK for OPTIONS (34)
1032. nua_stack.c:529 nua_signal() nua(0x7f0da0017360): sent signal r_respond
1033. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1034. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1035. nua_stack.c:569 nua_stack_signal() nua(0x7f0da0017360): recv signal r_destroy
1036. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
1037. soa.c:356 soa_destroy() soa_destroy(static::0x7f0da001e880) called
1038. nua_stack.c:529 nua_signal() nua(0x7f0da0017360): sent signal r_destroy
1039. 2017-10-17 17:21:11.632625 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 2510/2511 flaws: 1 mos: 4.49 v: 117.11 105.55/266.43
1040. nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response
1041. nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f0daedefc60)
1042. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/1 resent, 0/1 tout, 1/2 term, 1/3 free
1043. nta.c:1296 agent_timer() nta: timer set next to 697 ms
1044. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
1045. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
1046. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
1047. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
1048. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
1049. tport.c:3492 tport_send_msg() tport_vsend returned 891
1050. send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:13.481759:
1051.    ------------------------------------------------------------------------
1052.    SIP/2.0 200 OK
1053.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
1054.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
1055.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
1056.    Call-ID: 100201@10.95.2.2:5060
1057.    CSeq: 13 INVITE
1058.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
1059.    User-Agent: ECSCore
1060.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1061.    Supported: timer, path, replaces
1062.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1063.    Content-Type: application/sdp
1064.    Content-Disposition: session
1065.    Content-Length: 206
1066.  
1067.    v=0
1068.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
1069.    s=ECSCore
1070.    c=IN IP4 10.3.2.4
1071.    t=0 0
1072.    m=audio 18162 RTP/AVP 0 101
1073.    a=rtpmap:0 PCMU/8000
1074.    a=rtpmap:101 telephone-event/8000
1075.    a=fmtp:101 0-16
1076.    a=ptime:20
1077.    ------------------------------------------------------------------------
1078. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free
1079. nta.c:1296 agent_timer() nta: timer set next to 4000 ms
1080. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
1081. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
1082. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0012740 from (udp/10.3.2.4:5060) has 4 bytes, veclen = 1
1083. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): bad msg 0x7f0da0012740 (4 bytes) from udp/10.95.2.81:5060/sip next=(nil)
1084. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
1085. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
1086. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0012740 from (udp/10.3.2.4:5060) has 602 bytes, veclen = 1
1087. recv 602 bytes from udp/[10.95.2.81]:50461 at 17:21:15.250541:
1088.    ------------------------------------------------------------------------
1089.    SUBSCRIBE sip:1001@10.3.2.4:5060 SIP/2.0
1090.    Via: SIP/2.0/UDP 10.95.2.81:50461;branch=z9hG4bK-524287-1---10949e77dc307966;rport
1091.    Max-Forwards: 70
1092.    Contact: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
1093.    To: <sip:1001@10.3.2.4>;tag=7KqPYZsM5cVl
1094.    From: <sip:1001@10.3.2.4>;tag=3776e149
1095.    Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI
1096.    CSeq: 17 SUBSCRIBE
1097.    Expires: 300
1098.    Accept: application/simple-message-summary
1099.    Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, MESSAGE
1100.    User-Agent: Bria 4 release 4.8.2 stamp 85656
1101.    Event: message-summary
1102.    Content-Length: 0
1103.  
1104.    ------------------------------------------------------------------------
1105. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0012740 (602 bytes) from udp/10.95.2.81:5060/sip next=(nil)
1106. nta.c:2880 agent_recv_request() nta: received SUBSCRIBE sip:1001@10.3.2.4:5060 SIP/2.0 (CSeq 17)
1107. nta.c:3248 agent_aliases() nta: canonizing sip:1001@10.3.2.4:5060 with contact
1108. nta.c:3085 agent_recv_request() nta: SUBSCRIBE (17) going to a default leg
1109. nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
1110. nua_stack.c:899 nh_create() nua: nh_create: entering
1111. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
1112. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
1113. soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0da0004b00) called
1114. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0003240, ...) called
1115. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da0018290)
1116. nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f0da0004b00): adding notify usage with event message-summary
1117. nua_stack.c:271 nua_stack_event() nua(0x7f0da0004b00): event i_subscribe 100 Trying
1118. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1119. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1120. nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh notify after 300 seconds (in [300..300])
1121. nua.c:879 nua_respond() nua: nua_respond: entering
1122. nua_stack.c:573 nua_stack_signal() nua(0x7f0da0004b00): recv signal r_respond 202 Accepted
1123. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
1124. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0003240, ...) called
1125. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.81:50461
1126. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461
1127. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.81:50461
1128. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 719 bytes of 719 to udp/10.95.2.81:50461
1129. tport.c:3492 tport_send_msg() tport_vsend returned 719
1130. send 719 bytes to udp/[10.95.2.81]:50461 at 17:21:15.251936:
1131.    ------------------------------------------------------------------------
1132.    SIP/2.0 202 Accepted
1133.    Via: SIP/2.0/UDP 10.95.2.81:50461;branch=z9hG4bK-524287-1---10949e77dc307966;rport=50461
1134.    From: <sip:1001@10.3.2.4>;tag=3776e149
1135.    To: <sip:1001@10.3.2.4>;tag=7KqPYZsM5cVl
1136.    Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI
1137.    CSeq: 17 SUBSCRIBE
1138.    Contact: <sip:1001@10.3.2.4:5060>
1139.    Expires: 300
1140.    User-Agent: ECSCore
1141.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1142.    Supported: timer, path, replaces
1143.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1144.    Subscription-State: active;expires=300
1145.    Content-Length: 0
1146.  
1147.    ------------------------------------------------------------------------
1148. nta.c:6791 incoming_reply() nta: sent 202 Accepted for SUBSCRIBE (17)
1149. nua_stack.c:529 nua_signal() nua(0x7f0da0004b00): sent signal r_respond
1150. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1151. nua_stack.c:569 nua_stack_signal() nua(0x7f0da0004b00): recv signal r_destroy
1152. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f0da0004b00): removing notify usage with event message-summary
1153. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da0018290)
1154. soa.c:356 soa_destroy() soa_destroy(static::0x7f0da0003240) called
1155. nua_stack.c:529 nua_signal() nua(0x7f0da0004b00): sent signal r_destroy
1156. 2017-10-17 17:21:15.312570 [ALERT] switch_rtp.c:1658 sofia/internal/100201@10.95.2.2 Got: audio seq 28865 but expected: 28864 lost: 1
1157. 2017-10-17 17:21:15.312570 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 2877/2879 flaws: 2 mos: 4.49 v: 118.40 105.55/266.43
1158. nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
1159. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
1160. nua.c:716 nua_notify() nua: nua_notify: entering
1161. nua_stack.c:569 nua_stack_signal() nua(0x7f0d98034360): recv signal r_notify
1162. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
1163. soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0d98034360) called
1164. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da002fed0, ...) called
1165. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da002fed0, ...) called
1166. nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da0018290)
1167. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
1168. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.81:50461
1169. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461
1170. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.81:50461
1171. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 881 bytes of 881 to udp/10.95.2.81:50461
1172. tport.c:3492 tport_send_msg() tport_vsend returned 881
1173. send 881 bytes to udp/[10.95.2.81]:50461 at 17:21:15.340076:
1174.    ------------------------------------------------------------------------
1175.    NOTIFY sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7 SIP/2.0
1176.    Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKcracFHSKUvUce
1177.    Max-Forwards: 70
1178.    From: <sip:1001@10.3.2.4>;tag=7KqPYZsM5cVl
1179.    To: <sip:1001@10.3.2.4>;tag=3776e149
1180.    Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI
1181.    CSeq: 1251603751 NOTIFY
1182.    Contact: <sip:1001@10.3.2.4:5060>
1183.    User-Agent: ECSCore
1184.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1185.    Supported: timer, path, replaces
1186.    Event: message-summary
1187.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1188.    Subscription-State: active;expires=300
1189.    Content-Type: application/simple-message-summary
1190.    Content-Length: 60
1191.  
1192.    Messages-Waiting: no
1193.    Message-Account: sip:1001@10.3.2.4
1194.  
1195.    ------------------------------------------------------------------------
1196. nta.c:8304 outgoing_send() nta: sent NOTIFY (1251603751) to */10.95.2.81:50461
1197. tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da0003160 for udp/10.3.2.4:5060 (already 0)
1198. nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
1199. nua_stack.c:529 nua_signal() nua(0x7f0d98034360): sent signal r_notify
1200. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
1201. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
1202. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da002a010 from (udp/10.3.2.4:5060) has 380 bytes, veclen = 1
1203. recv 380 bytes from udp/[10.95.2.81]:50461 at 17:21:15.341065:
1204.    ------------------------------------------------------------------------
1205.    SIP/2.0 200 OK
1206.    Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bKcracFHSKUvUce
1207.    Contact: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
1208.    To: <sip:1001@10.3.2.4>;tag=3776e149
1209.    From: <sip:1001@10.3.2.4>;tag=7KqPYZsM5cVl
1210.    Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI
1211.    CSeq: 1251603751 NOTIFY
1212.    User-Agent: Bria 4 release 4.8.2 stamp 85656
1213.    Content-Length: 0
1214.  
1215.    ------------------------------------------------------------------------
1216. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da002a010 (380 bytes) from udp/10.95.2.81:5060/sip next=(nil)
1217. nta.c:3299 agent_recv_response() nta: received 200 OK for NOTIFY (1251603751)
1218. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
1219. nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 1.17 ms
1220. tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0003160 by 0x7f0da001d620 with 0x7f0da002a010
1221. nua_stack.c:271 nua_stack_event() nua(0x7f0d98034360): event r_notify 200 OK
1222. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1223. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1224. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
1225. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1226. nua_stack.c:569 nua_stack_signal() nua(0x7f0d98034360): recv signal r_destroy
1227. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da0018290)
1228. soa.c:356 soa_destroy() soa_destroy(static::0x7f0da002fed0) called
1229. nua_stack.c:529 nua_signal() nua(0x7f0d98034360): sent signal r_destroy
1230. nta.c:1296 agent_timer() nta: timer set next to 1141 ms
1231. 2017-10-17 17:21:16.652595 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 3011/3013 flaws: 2 mos: 4.49 v: 117.21 105.55/266.43
1232. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply
1233. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060
1234. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
1235. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060
1236. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060
1237. tport.c:3492 tport_send_msg() tport_vsend returned 891
1238. send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:17.482783:
1239.    ------------------------------------------------------------------------
1240.    SIP/2.0 200 OK
1241.    Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924
1242.    From: "100201" <sip:100201@10.95.2.2>;tag=123447
1243.    To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
1244.    Call-ID: 100201@10.95.2.2:5060
1245.    CSeq: 13 INVITE
1246.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
1247.    User-Agent: ECSCore
1248.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1249.    Supported: timer, path, replaces
1250.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
1251.    Content-Type: application/sdp
1252.    Content-Disposition: session
1253.    Content-Length: 206
1254.  
1255.    v=0
1256.    o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4
1257.    s=ECSCore
1258.    c=IN IP4 10.3.2.4
1259.    t=0 0
1260.    m=audio 18162 RTP/AVP 0 101
1261.    a=rtpmap:0 PCMU/8000
1262.    a=rtpmap:101 telephone-event/8000
1263.    a=fmtp:101 0-16
1264.    a=ptime:20
1265.    ------------------------------------------------------------------------
1266. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/2 term, 0/3 free
1267. nta.c:1296 agent_timer() nta: timer set next to 472 ms
1268. nta.c:9101 outgoing_timer_dk() nta: timer D fired, terminate INVITE (113792556)
1269. nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f0daedefd40)
1270. nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
1271. nta.c:1296 agent_timer() nta: timer set next to 1 ms
1272. nta.c:8982 outgoing_timer_bf() nta: timer F fired, terminating ACK (113792556)
1273. nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f0daedefd40)
1274. nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/1 term, 1/2 free
1275. nta.c:1296 agent_timer() nta: timer set next to 18 ms
1276. nta.c:7105 _nta_incoming_timer() nta: timer H fired, timeout and terminate 200 response
1277. nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering
1278. nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_error 408 ACK Timeout
1279. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
1280. soa.c:1784 soa_terminate() soa_terminate(static::0x7f0da0017b10) called
1281. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f0da0017b10) called
1282. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
1283. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.2:5060
1284. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060
1285. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.2:5060
1286. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 543 bytes of 543 to udp/10.95.2.2:5060
1287. tport.c:3492 tport_send_msg() tport_vsend returned 543
1288. send 543 bytes to udp/[10.95.2.2]:5060 at 17:21:17.974808:
1289.    ------------------------------------------------------------------------
1290.    BYE sip:100201@10.95.2.2:5060 SIP/2.0
1291.    Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKD134gcaQr5HZS
1292.    Max-Forwards: 70
1293.    From: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
1294.    To: "100201" <sip:100201@10.95.2.2>;tag=123447
1295.    Call-ID: 100201@10.95.2.2:5060
1296.    CSeq: 113792574 BYE
1297.    Contact: <sip:30161@10.3.2.4:5060;transport=udp>
1298.    User-Agent: ECSCore
1299.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1300.    Supported: timer, path, replaces
1301.    Reason: SIP;cause=408;text="ACK Timeout"
1302.    Content-Length: 0
1303.  
1304.    ------------------------------------------------------------------------
1305. nta.c:8304 outgoing_send() nta: sent BYE (113792574) to */10.95.2.2:5060
1306. tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da0010400 for udp/10.3.2.4:5060 (already 0)
1307. nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: completed -> terminating
1308. nua_stack.c:269 nua_stack_event() nua(0x7f0da00130b0): event i_state ACK Timeout
1309. nta.c:5744 incoming_free() nta: incoming_free(0x7f0da00112a0)
1310. nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/1 resent, 1/1 tout, 0/2 term, 0/3 free
1311. nta.c:1296 agent_timer() nta: timer set next to 1001 ms
1312. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1313. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1314. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
1315. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
1316. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0018400 from (udp/10.3.2.4:5060) has 276 bytes, veclen = 1
1317. recv 276 bytes from udp/[10.95.2.2]:5060 at 17:21:17.977778:
1318.    ------------------------------------------------------------------------
1319.    SIP/2.0 200 OK
1320.    To: "100201" <sip:100201@10.95.2.2>;tag=123447
1321.    From: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
1322.    Call-ID: 100201@10.95.2.2:5060
1323.    CSeq: 113792574 BYE
1324.    Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKD134gcaQr5HZS
1325.    User-Agent: TATTILE PBX v.3.4
1326.    Content-Length: 0
1327.  
1328.    ------------------------------------------------------------------------
1329. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0018400 (276 bytes) from udp/10.95.2.2:5060/sip next=(nil)
1330. nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (113792574)
1331. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
1332. nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 3.156 ms
1333. tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0010400 by 0x7f0da0029e40 with 0x7f0da0018400
1334. nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event r_bye 200 OK
1335. nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: terminating -> terminated
1336. nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_state 200 to BYE
1337. nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_terminated 200 to BYE
1338. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f0da00130b0): removing session usage
1339. soa.c:356 soa_destroy() soa_destroy(static::0x7f0da0017b10) called
1340. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da0022e90)
1341. nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f0da00130b0
1342. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1343. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1344. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1345. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1346. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1347. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1348. 2017-10-17 17:21:17.953318 [DEBUG] sofia.c:7048 Channel sofia/internal/100201@10.95.2.2 entering state [terminating][0]
1349. 2017-10-17 17:21:17.953318 [NOTICE] sofia.c:8237 Hangup sofia/internal/100201@10.95.2.2 [CS_EXECUTE] [NORMAL_UNSPECIFIED]
1350. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
1351. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1352. nua_stack.c:569 nua_stack_signal() nua(0x7f0da00130b0): recv signal r_destroy
1353. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
1354. nua_stack.c:529 nua_signal() nua(0x7f0da00130b0): sent signal r_destroy
1355. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1356. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
1357. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1358. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1359. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1360. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1361. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1362. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1363. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1364. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1365. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1366. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1367. 2017-10-17 17:21:17.953318 [DEBUG] switch_ivr_bridge.c:712 sofia/internal/100201@10.95.2.2 ending bridge by request from read function
1368. 2017-10-17 17:21:17.953318 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/100201@10.95.2.2]
1369. 2017-10-17 17:21:17.992576 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/100201@10.95.2.2 ending bridge by request from write function
1370. 2017-10-17 17:21:17.992576 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/1001@10.95.2.81:50461]
1371. 2017-10-17 17:21:17.992576 [NOTICE] switch_ivr_bridge.c:891 Hangup sofia/internal/1001@10.95.2.81:50461 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
1372. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1001@10.95.2.81:50461) State EXCHANGE_MEDIA going to sleep
1373. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_HANGUP (Cur 2 Tot 26)
1374. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1001@10.95.2.81:50461) Callstate Change ACTIVE -> HANGUP
1375. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@10.95.2.81:50461) State HANGUP
1376. 2017-10-17 17:21:17.992576 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1001@10.95.2.81:50461 hanging up, cause: NORMAL_CLEARING
1377. 2017-10-17 17:21:17.992576 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/1001@10.95.2.81:50461
1378. nua.c:645 nua_bye() nua: nua_bye: entering
1379. nua_stack.c:569 nua_stack_signal() nua(0x7f0d98031830): recv signal r_bye
1380. nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
1381. soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017760, ...) called
1382. soa.c:1784 soa_terminate() soa_terminate(static::0x7f0da0017760) called
1383. soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f0da0017760) called
1384. nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
1385. tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.81:50461
1386. tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461
1387. tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.81:50461
1388. tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 575 bytes of 575 to udp/10.95.2.81:50461
1389. tport.c:3492 tport_send_msg() tport_vsend returned 575
1390. send 575 bytes to udp/[10.95.2.81]:50461 at 17:21:18.000064:
1391.    ------------------------------------------------------------------------
1392.    BYE sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7 SIP/2.0
1393.    Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKeaXXj7ttNe8HN
1394.    Max-Forwards: 70
1395.    From: "100201" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
1396.    To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
1397.    Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
1398.    CSeq: 113792557 BYE
1399.    User-Agent: ECSCore
1400.    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
1401.    Supported: timer, path, replaces
1402.    Reason: Q.850;cause=16;text="NORMAL_CLEARING"
1403.    Content-Length: 0
1404.  
1405.    ------------------------------------------------------------------------
1406. nta.c:8304 outgoing_send() nta: sent BYE (113792557) to */10.95.2.81:50461
1407. tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da001bb30 for udp/10.3.2.4:5060 (already 0)
1408. nua_stack.c:529 nua_signal() nua(0x7f0d98031830): sent signal r_bye
1409. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@10.95.2.81:50461 Standard HANGUP, cause: NORMAL_CLEARING
1410. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@10.95.2.81:50461) State HANGUP going to sleep
1411. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1001@10.95.2.81:50461) State Change CS_HANGUP -> CS_REPORTING
1412. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_REPORTING (Cur 2 Tot 26)
1413. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@10.95.2.81:50461) State REPORTING
1414. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1001@10.95.2.81:50461 Standard REPORTING, cause: NORMAL_CLEARING
1415. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@10.95.2.81:50461) State REPORTING going to sleep
1416. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1001@10.95.2.81:50461) State Change CS_REPORTING -> CS_DESTROY
1417. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_session.c:1664 Session 26 (sofia/internal/1001@10.95.2.81:50461) Locked, Waiting on external entities
1418. 2017-10-17 17:21:17.992576 [ALERT] switch_ivr_bridge.c:1702 sofia/internal/100201@10.95.2.2 receive message [UNBRIDGE]
1419. 2017-10-17 17:21:17.992576 [DEBUG] switch_ivr_bridge.c:1702 sofia/internal/100201@10.95.2.2 skip receive message [UNBRIDGE] (channel is hungup already)
1420. 2017-10-17 17:21:17.992576 [ALERT] switch_core_session.c:2814 sofia/internal/100201@10.95.2.2 receive message [APPLICATION_EXEC_COMPLETE]
1421. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_session.c:2814 sofia/internal/100201@10.95.2.2 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
1422. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/100201@10.95.2.2) State EXECUTE going to sleep
1423. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_HANGUP (Cur 2 Tot 26)
1424. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100201@10.95.2.2) Callstate Change ACTIVE -> HANGUP
1425. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100201@10.95.2.2) State HANGUP
1426. 2017-10-17 17:21:17.992576 [DEBUG] mod_sofia.c:438 Channel sofia/internal/100201@10.95.2.2 hanging up, cause: NORMAL_UNSPECIFIED
1427. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100201@10.95.2.2 Standard HANGUP, cause: NORMAL_UNSPECIFIED
1428. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100201@10.95.2.2) State HANGUP going to sleep
1429. 2017-10-17 17:21:17.992576 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 3142/3144 flaws: 2 mos: 4.49 v: 117.58 105.55/266.43
1430. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/100201@10.95.2.2) State Change CS_HANGUP -> CS_REPORTING
1431. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_REPORTING (Cur 2 Tot 26)
1432. 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100201@10.95.2.2) State REPORTING
1433. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100201@10.95.2.2 Standard REPORTING, cause: NORMAL_UNSPECIFIED
1434. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100201@10.95.2.2) State REPORTING going to sleep
1435. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/100201@10.95.2.2) State Change CS_REPORTING -> CS_DESTROY
1436. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_session.c:1664 Session 25 (sofia/internal/100201@10.95.2.2) Locked, Waiting on external entities
1437. 2017-10-17 17:21:18.012579 [NOTICE] switch_core_session.c:1682 Session 25 (sofia/internal/100201@10.95.2.2) Ended
1438. 2017-10-17 17:21:18.012579 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/100201@10.95.2.2 [CS_DESTROY]
1439. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/100201@10.95.2.2) Running State Change CS_DESTROY (Cur 1 Tot 26)
1440. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100201@10.95.2.2) State DESTROY
1441. 2017-10-17 17:21:18.012579 [DEBUG] mod_sofia.c:343 sofia/internal/100201@10.95.2.2 SOFIA DESTROY
1442. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100201@10.95.2.2 Standard DESTROY
1443. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100201@10.95.2.2) State DESTROY going to sleep
1444. 2017-10-17 17:21:18.012579 [NOTICE] switch_core_session.c:1682 Session 26 (sofia/internal/1001@10.95.2.81:50461) Ended
1445. 2017-10-17 17:21:18.012579 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1001@10.95.2.81:50461 [CS_DESTROY]
1446. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_DESTROY (Cur 0 Tot 26)
1447. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@10.95.2.81:50461) State DESTROY
1448. 2017-10-17 17:21:18.012579 [DEBUG] mod_sofia.c:343 sofia/internal/1001@10.95.2.81:50461 SOFIA DESTROY
1449. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1001@10.95.2.81:50461 Standard DESTROY
1450. 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@10.95.2.81:50461) State DESTROY going to sleep
1451. tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN
1452. tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0)
1453. tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0021ad0 from (udp/10.3.2.4:5060) has 411 bytes, veclen = 1
1454. recv 411 bytes from udp/[10.95.2.81]:50461 at 17:21:18.151413:
1455.    ------------------------------------------------------------------------
1456.    SIP/2.0 200 OK
1457.    Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bKeaXXj7ttNe8HN
1458.    Contact: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
1459.    To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
1460.    From: "100201" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
1461.    Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
1462.    CSeq: 113792557 BYE
1463.    User-Agent: Bria 4 release 4.8.2 stamp 85656
1464.    Content-Length: 0
1465.  
1466.    ------------------------------------------------------------------------
1467. tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0021ad0 (411 bytes) from udp/10.95.2.81:5060/sip next=(nil)
1468. nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (113792557)
1469. nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
1470. nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 154.556 ms
1471. tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da001bb30 by 0x7f0da00054c0 with 0x7f0da0021ad0
1472. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event r_bye 200 OK
1473. nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: terminating -> terminated
1474. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_state 200 to BYE
1475. nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_terminated 200 to BYE
1476. nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f0d98031830): removing session usage
1477. soa.c:356 soa_destroy() soa_destroy(static::0x7f0da0017760) called
1478. nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da001c9f0)
1479. nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f0d98031830
1480. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1481. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1482. nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
1483. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1484. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1485. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1486. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1487. nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
1488. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1489. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
1490. nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
1491. nua_stack.c:569 nua_stack_signal() nua(0x7f0d98031830): recv signal r_destroy
1492. nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
1493. nua_stack.c:529 nua_signal() nua(0x7f0d98031830): sent signal r_destroy
1494. nta.c:1296 agent_timer() nta: timer set next to 1366 ms
1495.