1. 2018-05-27 09:20:19.387823 [INFO] mod_pocketsphinx.c:644 PocketSphinx Reloaded
2. 2018-05-27 09:20:19.387823 [INFO] mod_enum.c:879 ENUM Reloaded
3. 2018-05-27 09:20:19.387823 [INFO] switch_time.c:1423 Timezone reloaded 1750 definitions
4. 2018-05-27 09:20:24.268069 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/353758081570968@192.168.1.97 [c1345991-1b47-44ba-bd57-baca2ba0b136]
5. 2018-05-27 09:20:24.268069 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/353758081570968@192.168.1.97) Running State Change CS_NEW (Cur 1 Tot 15)
6. 2018-05-27 09:20:24.268069 [DEBUG] sofia.c:9873 sofia/internal/353758081570968@192.168.1.97 receiving invite from 192.168.1.99:5061 version: 1.6.20 -37-987c9b9 64bit
7. 2018-05-27 09:20:24.268069 [DEBUG] sofia.c:10044 IP 192.168.1.99 Rejected by acl "domains". Falling back to Digest auth.
8. 2018-05-27 09:20:24.268069 [DEBUG] sofia.c:2334 detaching session c1345991-1b47-44ba-bd57-baca2ba0b136
9. 2018-05-27 09:20:24.268069 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [C8DF84425410@192.168.1.97] from ip 192.168.1.99
10. 2018-05-27 09:20:24.268069 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/353758081570968@192.168.1.97) State NEW
11. 2018-05-27 09:20:24.307433 [DEBUG] sofia.c:2442 Re-attaching to session c1345991-1b47-44ba-bd57-baca2ba0b136
12. 2018-05-27 09:20:24.307433 [DEBUG] sofia.c:9873 sofia/internal/353758081570968@192.168.1.97 receiving invite from 192.168.1.99:5061 version: 1.6.20 -37-987c9b9 64bit
13. 2018-05-27 09:20:24.307433 [DEBUG] sofia.c:10044 IP 192.168.1.99 Rejected by acl "domains". Falling back to Digest auth.
14. 2018-05-27 09:20:24.317917 [DEBUG] sofia.c:7084 Channel sofia/internal/353758081570968@192.168.1.97 entering state [received][100]
15. 2018-05-27 09:20:24.317917 [DEBUG] sofia.c:7094 Remote SDP:
16. v=0
17. o=353758081570968 2505 2014 IN IP4 192.168.1.99
18. s=Talk
19. c=IN IP4 192.168.1.99
20. t=0 0
21. a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
22. m=audio 7078 RTP/AVP 0 101
23. a=rtpmap:101 telephone-event/8000
24. a=rtcp-fb:* trr-int 5000
25. a=rtcp-fb:* ccm tmmbr
26. m=video 9078 RTP/AVP 96
27. a=rtpmap:96 H264/90000
28. a=fmtp:96 profile-level-id=42801F
29. a=rtcp-fb:* trr-int 5000
30. a=rtcp-fb:* ccm tmmbr
31. a=rtcp-fb:96 nack pli
32. a=rtcp-fb:96 ccm fir
33.  
34. 2018-05-27 09:20:24.317917 [DEBUG] sofia.c:7486 (sofia/internal/353758081570968@192.168.1.97) State Change CS_NEW -> CS_INIT
35. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/353758081570968@192.168.1.97) Running State Change CS_INIT (Cur 1 Tot 15)
36. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/353758081570968@192.168.1.97) State INIT
37. 2018-05-27 09:20:24.317917 [DEBUG] mod_sofia.c:90 sofia/internal/353758081570968@192.168.1.97 SOFIA INIT
38. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:40 sofia/internal/353758081570968@192.168.1.97 Standard INIT
39. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/353758081570968@192.168.1.97) State Change CS_INIT -> CS_ROUTING
40. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/353758081570968@192.168.1.97) State INIT going to sleep
41. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/353758081570968@192.168.1.97) Running State Change CS_ROUTING (Cur 1 Tot 15)
42. 2018-05-27 09:20:24.317917 [DEBUG] switch_channel.c:2249 (sofia/internal/353758081570968@192.168.1.97) Callstate Change DOWN -> RINGING
43. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/353758081570968@192.168.1.97) State ROUTING
44. 2018-05-27 09:20:24.317917 [DEBUG] mod_sofia.c:143 sofia/internal/353758081570968@192.168.1.97 SOFIA ROUTING
45. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:236 sofia/internal/353758081570968@192.168.1.97 Standard ROUTING
46. 2018-05-27 09:20:24.317917 [INFO] mod_dialplan_xml.c:637 Processing 353758081570968 <353758081570968>->C8DF84425410 in context default
47. Dialplan: sofia/internal/353758081570968@192.168.1.97 parsing [default->C8DF84425410] continue=false
48. Dialplan: sofia/internal/353758081570968@192.168.1.97 Regex (PASS) [C8DF84425410] destination_number(C8DF84425410) =~ /^(([0-9a-fA-F]){12})$/ break=on-false
49. Dialplan: sofia/internal/353758081570968@192.168.1.97 Action export(dialed_extension=C8DF84425410)
50. Dialplan: sofia/internal/353758081570968@192.168.1.97 Action set(enable_file_write_buffering=false)
51. Dialplan: sofia/internal/353758081570968@192.168.1.97 Action set(RECORD_STEREO=true)
52. Dialplan: sofia/internal/353758081570968@192.168.1.97 Action set(execute_on_answer=record_session /var/lib/freeswitch/recordings/WITH_${strftime(%Y-%m-%d-%H-%M-%S)}.mp4)
53. Dialplan: sofia/internal/353758081570968@192.168.1.97 Action bridge(user/${dialed_extension}@${domain_name})
54. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/353758081570968@192.168.1.97) State Change CS_ROUTING -> CS_EXECUTE
55. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/353758081570968@192.168.1.97) State ROUTING going to sleep
56. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/353758081570968@192.168.1.97) Running State Change CS_EXECUTE (Cur 1 Tot 15)
57. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/353758081570968@192.168.1.97) State EXECUTE
58. 2018-05-27 09:20:24.317917 [DEBUG] mod_sofia.c:198 sofia/internal/353758081570968@192.168.1.97 SOFIA EXECUTE
59. 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:328 sofia/internal/353758081570968@192.168.1.97 Standard EXECUTE
60. EXECUTE sofia/internal/353758081570968@192.168.1.97 export(dialed_extension=C8DF84425410)
61. 2018-05-27 09:20:24.317917 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[C8DF84425410]
62. EXECUTE sofia/internal/353758081570968@192.168.1.97 set(enable_file_write_buffering=false)
63. 2018-05-27 09:20:24.317917 [DEBUG] mod_dptools.c:1548 SET sofia/internal/353758081570968@192.168.1.97 [enable_file_write_buffering]=[false]
64. EXECUTE sofia/internal/353758081570968@192.168.1.97 set(RECORD_STEREO=true)
65. 2018-05-27 09:20:24.317917 [DEBUG] mod_dptools.c:1548 SET sofia/internal/353758081570968@192.168.1.97 [RECORD_STEREO]=[true]
66. EXECUTE sofia/internal/353758081570968@192.168.1.97 set(execute_on_answer=record_session /var/lib/freeswitch/recordings/WITH_2018-05-27-09-20-24.mp4)
67. 2018-05-27 09:20:24.317917 [DEBUG] mod_dptools.c:1548 SET sofia/internal/353758081570968@192.168.1.97 [execute_on_answer]=[record_session /var/lib/freeswitch/recordings/WITH_2018-05-27-09-20-24.mp4]
68. EXECUTE sofia/internal/353758081570968@192.168.1.97 bridge(user/C8DF84425410@192.168.1.97)
69. 2018-05-27 09:20:24.317917 [DEBUG] switch_channel.c:1250 sofia/internal/353758081570968@192.168.1.97 EXPORTING[export_vars] [dialed_extension]=[C8DF84425410] to event
70. 2018-05-27 09:20:24.317917 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
71. 2018-05-27 09:20:24.327396 [DEBUG] switch_channel.c:1250 sofia/internal/353758081570968@192.168.1.97 EXPORTING[export_vars] [dialed_extension]=[C8DF84425410] to event
72. 2018-05-27 09:20:24.327396 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
73. 2018-05-27 09:20:24.327396 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/C8DF84425410@192.168.1.108:5060 [e712ec82-320c-45d3-b506-41b2a99ee512]
74. 2018-05-27 09:20:24.327396 [DEBUG] mod_sofia.c:4819 (sofia/internal/C8DF84425410@192.168.1.108:5060) State Change CS_NEW -> CS_INIT
75. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/C8DF84425410@192.168.1.108:5060) Running State Change CS_INIT (Cur 2 Tot 16)
76. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/C8DF84425410@192.168.1.108:5060) State INIT
77. 2018-05-27 09:20:24.327396 [DEBUG] mod_sofia.c:90 sofia/internal/C8DF84425410@192.168.1.108:5060 SOFIA INIT
78. 2018-05-27 09:20:24.327396 [DEBUG] sofia_glue.c:1295 sofia/internal/C8DF84425410@192.168.1.108:5060 sending invite version: 1.6.20 -37-987c9b9 64bit
79. Local SDP:
80. v=0
81. o=FreeSWITCH 1527401382 1527401383 IN IP4 192.168.1.97
82. s=FreeSWITCH
83. c=IN IP4 192.168.1.97
84. t=0 0
85. m=audio 25842 RTP/AVP 0 101
86. a=rtpmap:0 PCMU/8000
87. a=rtpmap:101 telephone-event/8000
88. a=fmtp:101 0-16
89. a=ptime:20
90. a=sendrecv
91. m=video 30732 RTP/AVP 96
92. b=AS:1024
93. a=rtpmap:96 H264/90000
94. a=fmtp:96 profile-level-id=42801F
95. a=rtcp-fb:96 ccm fir
96. a=rtcp-fb:96 ccm tmmbr
97. a=rtcp-fb:96 nack
98. a=rtcp-fb:96 nack pli
99.  
100. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:40 sofia/internal/C8DF84425410@192.168.1.108:5060 Standard INIT
101. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/C8DF84425410@192.168.1.108:5060) State Change CS_INIT -> CS_ROUTING
102. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/C8DF84425410@192.168.1.108:5060) State INIT going to sleep
103. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/C8DF84425410@192.168.1.108:5060) Running State Change CS_ROUTING (Cur 2 Tot 16)
104. 2018-05-27 09:20:24.327396 [DEBUG] sofia.c:7084 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 entering state [calling][0]
105. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/C8DF84425410@192.168.1.108:5060) State ROUTING
106. 2018-05-27 09:20:24.327396 [DEBUG] mod_sofia.c:143 sofia/internal/C8DF84425410@192.168.1.108:5060 SOFIA ROUTING
107. 2018-05-27 09:20:24.327396 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/C8DF84425410@192.168.1.108:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
108. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/C8DF84425410@192.168.1.108:5060) State ROUTING going to sleep
109. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/C8DF84425410@192.168.1.108:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 16)
110. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/C8DF84425410@192.168.1.108:5060) State CONSUME_MEDIA
111. 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/C8DF84425410@192.168.1.108:5060) State CONSUME_MEDIA going to sleep
112. 2018-05-27 09:20:24.517932 [DEBUG] sofia.c:7084 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 entering state [proceeding][180]
113. 2018-05-27 09:20:24.517932 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/C8DF84425410@192.168.1.108:5060!
114. 2018-05-27 09:20:24.517932 [DEBUG] switch_channel.c:3346 (sofia/internal/C8DF84425410@192.168.1.108:5060) Callstate Change DOWN -> RINGING
115. 2018-05-27 09:20:24.517932 [DEBUG] sofia.c:7084 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 entering state [completing][200]
116. 2018-05-27 09:20:24.517932 [DEBUG] sofia.c:7094 Remote SDP:
117. v=0
118. o=C8DF84425410 0 0 IN IP4 192.168.1.108
119. c=IN IP4 192.168.1.108
120. t=0 0
121. m=audio 9002 RTP/AVP 0 101
122. a=rtpmap:0 PCMU/8000
123. a=rtpmap:101 telephone-event/8000
124. m=video 9000 RTP/AVP 96
125. a=rtpmap:96 H264/90000
126. a=fmtp:96 packetization-mode=1;profile-level-id=42801f;sprop-parameter-sets=Z0IAH52oFAFum4CAgIE=,aM48gA==;
127. a=sendonly
128.  
129. 2018-05-27 09:20:24.517932 [DEBUG] sofia.c:7084 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 entering state [ready][200]
130. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
131. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
132. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
133. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/C8DF84425410@192.168.1.108:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
134. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_codec.c:111 sofia/internal/C8DF84425410@192.168.1.108:5060 Original read codec set to PCMU:0
135. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
136. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4767 sofia/internal/C8DF84425410@192.168.1.108:5060 Set 2833 dtmf send payload to 101 recv payload to 101
137. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4950 Video Codec Compare [H264:96]/[H264:99]
138. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4993 No matches with FTMP, fallback to ignoring FMTP
139. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4950 Video Codec Compare [H264:96]/[H264:99]
140. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4982 Video Codec Compare [H264:96] +++ is saved as a match
141. 2018-05-27 09:20:24.517932 [NOTICE] avcodec.c:1022 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
142. 2018-05-27 09:20:24.517932 [NOTICE] avcodec.c:1022 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
143. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:2871 Set VIDEO Codec sofia/internal/C8DF84425410@192.168.1.108:5060 H264/90000 0 ms
144. 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/C8DF84425410@192.168.1.108:5060] 192.168.1.97 port 25842 -> 192.168.1.108 port 9002 codec: 0 ms: 20
145. 2018-05-27 09:20:24.527777 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
146. 2018-05-27 09:20:24.527777 [DEBUG] switch_core_media.c:7180 sofia/internal/C8DF84425410@192.168.1.108:5060 Set 2833 dtmf send payload to 101
147. 2018-05-27 09:20:24.527777 [DEBUG] switch_core_media.c:7187 sofia/internal/C8DF84425410@192.168.1.108:5060 Set 2833 dtmf receive payload to 101
148. 2018-05-27 09:20:24.527777 [DEBUG] switch_core_media.c:7210 sofia/internal/C8DF84425410@192.168.1.108:5060 Set rtp dtmf delay to 40
149. 2018-05-27 09:20:24.527777 [DEBUG] switch_rtp.c:4152 Starting video timer.
150. 2018-05-27 09:20:24.527777 [DEBUG] switch_core_media.c:7399 VIDEO RTP [sofia/internal/C8DF84425410@192.168.1.108:5060] 192.168.1.97:30732->192.168.1.108:9000 codec: 96 ms: 0 [SUCCESS]
151. 2018-05-27 09:20:24.527777 [DEBUG] switch_core_media.c:6003 sofia/internal/C8DF84425410@192.168.1.108:5060 Starting Video thread
152. 2018-05-27 09:20:24.527777 [DEBUG] switch_core_media.c:5869 sofia/internal/C8DF84425410@192.168.1.108:5060 Video thread started. Echo is off
153. 2018-05-27 09:20:24.527777 [NOTICE] sofia.c:8218 Channel [sofia/internal/C8DF84425410@192.168.1.108:5060] has been answered
154. 2018-05-27 09:20:24.527777 [DEBUG] switch_channel.c:3773 (sofia/internal/C8DF84425410@192.168.1.108:5060) Callstate Change RINGING -> ACTIVE
155. 2018-05-27 09:20:24.538220 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/internal/353758081570968@192.168.1.97!
156. 2018-05-27 09:20:24.538220 [DEBUG] sofia.c:7084 Channel sofia/internal/353758081570968@192.168.1.97 entering state [early][180]
157. 2018-05-27 09:20:24.538220 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/internal/353758081570968@192.168.1.97!
158. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
159. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
160. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
161. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/353758081570968@192.168.1.97 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
162. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_codec.c:111 sofia/internal/353758081570968@192.168.1.97 Original read codec set to PCMU:0
163. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
164. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4767 sofia/internal/353758081570968@192.168.1.97 Set 2833 dtmf send payload to 101 recv payload to 101
165. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4950 Video Codec Compare [H264:96]/[H264:99]
166. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4982 Video Codec Compare [H264:96] +++ is saved as a match
167. 2018-05-27 09:20:24.538220 [NOTICE] avcodec.c:1022 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
168. 2018-05-27 09:20:24.538220 [NOTICE] avcodec.c:1022 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
169. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:2871 Set VIDEO Codec sofia/internal/353758081570968@192.168.1.97 H264/90000 0 ms
170. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/353758081570968@192.168.1.97] 192.168.1.97 port 23316 -> 192.168.1.99 port 7078 codec: 0 ms: 20
171. 2018-05-27 09:20:24.538220 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
172. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:7180 sofia/internal/353758081570968@192.168.1.97 Set 2833 dtmf send payload to 101
173. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:7187 sofia/internal/353758081570968@192.168.1.97 Set 2833 dtmf receive payload to 101
174. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:7210 sofia/internal/353758081570968@192.168.1.97 Set rtp dtmf delay to 40
175. 2018-05-27 09:20:24.538220 [DEBUG] switch_rtp.c:4152 Starting video timer.
176. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:7399 VIDEO RTP [sofia/internal/353758081570968@192.168.1.97] 192.168.1.97:29112->192.168.1.99:9078 codec: 96 ms: 0 [SUCCESS]
177. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:6003 sofia/internal/353758081570968@192.168.1.97 Starting Video thread
178. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:5869 sofia/internal/353758081570968@192.168.1.97 Video thread started. Echo is off
179. 2018-05-27 09:20:24.538220 [INFO] switch_core_media.c:7479 Activating VIDEO RTCP PORT 9079 interval 1000 mux -1
180. 2018-05-27 09:20:24.538220 [DEBUG] switch_rtp.c:4533 RTCP send rate is: 1000 and packet rate is: 90000 Remote Port: 9079
181. 2018-05-27 09:20:24.538220 [DEBUG] switch_rtp.c:2567 Setting RTCP remote addr to 192.168.1.99:9079 2
182. 2018-05-27 09:20:24.538220 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/353758081570968@192.168.1.97!
183. 2018-05-27 09:20:24.538220 [DEBUG] switch_channel.c:3474 (sofia/internal/353758081570968@192.168.1.97) Callstate Change RINGING -> EARLY
184. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/353758081570968@192.168.1.97.
185. 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:7257 Video params are unchanged for sofia/internal/353758081570968@192.168.1.97.
186. 2018-05-27 09:20:24.538220 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/353758081570968@192.168.1.97:
187. v=0
188. o=FreeSWITCH 1527403908 1527403909 IN IP4 192.168.1.97
189. s=FreeSWITCH
190. c=IN IP4 192.168.1.97
191. t=0 0
192. m=audio 23316 RTP/AVP 0 101
193. a=rtpmap:0 PCMU/8000
194. a=rtpmap:101 telephone-event/8000
195. a=fmtp:101 0-16
196. a=ptime:20
197. a=sendrecv
198. m=video 29112 RTP/AVP 96
199. b=AS:1024
200. a=rtpmap:96 H264/90000
201. a=fmtp:96 profile-level-id=42801F
202. a=rtcp:29113 IN IP4 192.168.1.97
203. a=rtcp-fb:96 ccm fir
204. a=rtcp-fb:96 ccm tmmbr
205. a=rtcp-fb:96 nack
206. a=rtcp-fb:96 nack pli
207.  
208. 2018-05-27 09:20:24.547680 [DEBUG] sofia.c:7084 Channel sofia/internal/353758081570968@192.168.1.97 entering state [completed][200]
209. 2018-05-27 09:20:24.547680 [NOTICE] switch_ivr_originate.c:3647 Channel [sofia/internal/353758081570968@192.168.1.97] has been answered
210. EXECUTE sofia/internal/353758081570968@192.168.1.97 record_session(/var/lib/freeswitch/recordings/WITH_2018-05-27-09-20-24.mp4)
211. 2018-05-27 09:20:24.547680 [DEBUG] avformat.c:1919 sample rate: 8000, channels: 2
212. 2018-05-27 09:20:24.547680 [DEBUG] avformat.c:2037 use video codec: [28] h264 (H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10)
213. 2018-05-27 09:20:24.547680 [NOTICE] avformat.c:648 sample_rate: 8000 nb_samples: 1024
214. Output #0, mp4, to '/var/lib/freeswitch/recordings/WITH_2018-05-27-09-20-24.mp4':
215.     Stream #0.0
216. : Audio: libvo_aacenc, 8000 Hz, stereo, s16, 131 kb/s
217. 2018-05-27 09:20:24.547680 [INFO] avformat.c:2061 Opening File [/var/lib/freeswitch/recordings/WITH_2018-05-27-09-20-24.mp4] 8000hz  with VIDEO
218. 2018-05-27 09:20:24.558509 [DEBUG] switch_core_media_bug.c:945 Attaching BUG to sofia/internal/353758081570968@192.168.1.97
219. 2018-05-27 09:20:24.558509 [DEBUG] switch_channel.c:3773 (sofia/internal/353758081570968@192.168.1.97) Callstate Change EARLY -> ACTIVE
220. 2018-05-27 09:20:24.558509 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/internal/C8DF84425410@192.168.1.108:5060]
221. 2018-05-27 09:20:24.558509 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/internal/C8DF84425410@192.168.1.108:5060]
222. 2018-05-27 09:20:24.558509 [DEBUG] switch_ivr_bridge.c:1614 (sofia/internal/C8DF84425410@192.168.1.108:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
223. 2018-05-27 09:20:24.558509 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/C8DF84425410@192.168.1.108:5060) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 16)
224. 2018-05-27 09:20:24.558509 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/C8DF84425410@192.168.1.108:5060) State EXCHANGE_MEDIA
225. 2018-05-27 09:20:24.558509 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
226. 2018-05-27 09:20:24.558509 [DEBUG] switch_ivr_async.c:1500 No silence detection configured; assuming start of speech
227. 2018-05-27 09:20:24.617540 [DEBUG] sofia.c:7084 Channel sofia/internal/353758081570968@192.168.1.97 entering state [ready][200]
228. 2018-05-27 09:20:24.628405 [INFO] avcodec.c:1083 initializing encoder 352x288
229. 2018-05-27 09:20:24.628405 [DEBUG] avcodec.c:832 NVENC HW CODEC NOT PRESENT
230. using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2
231. profile Constrained Baseline, level 3.1
232. 2018-05-27 09:20:24.647572 [INFO] avcodec.c:1083 initializing encoder 352x288
233. 2018-05-27 09:20:24.647572 [DEBUG] avcodec.c:832 NVENC HW CODEC NOT PRESENT
234. using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2
235. profile Constrained Baseline, level 3.1
236. 2018-05-27 09:20:24.657543 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
237. 2018-05-27 09:20:24.657543 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
238. 2018-05-27 09:20:24.807552 [DEBUG] switch_rtp.c:6758 Correct video RTCP ip/port confirmed.
239. 2018-05-27 09:20:25.018159 [DEBUG] switch_rtp.c:1887 rtcp_stats_init: video ssrc[3354518260] base_seq[0]
240. 2018-05-27 09:20:25.077544 [DEBUG] switch_rtp.c:7308 Correct video ip/port confirmed.
241. 2018-05-27 09:20:25.087508 [DEBUG] avcodec.c:1091 picture size changed from 352x288 to 640x480, reinitializing encoder
242. frame I:1     Avg QP: 3.00  size:  1072
243. mb I  I16..4: 99.7%  0.0%  0.3%
244. coded y,uvDC,uvAC intra: 0.1% 0.0% 0.0%
245. i16 v,h,dc,p: 95%  0%  5%  0%
246. i4 v,h,dc,ddl,ddr,vr,hd,vl,hu:  0%  0% 100%  0%  0%  0%  0%  0%  0%
247. i8c dc,h,v,p: 100%  0%  0%  0%
248. kb/s:771.84
249. using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2
250. profile Constrained Baseline, level 3.1
251. using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2
252. profile Constrained Baseline, level 4.1
253. 264 - core 142 r2431 a5831aa - H.264/MPEG-4 AVC codec - Copyleft 2003-2014 - http://www.videolan.org/x264.html - options: cabac=0 ref=1 deblock=1:0:0 analyse=0x1:0x111 me=hex subme=2 psy=1 psy_rd=1.00:0.00 mixed_ref=0 me_range=16 chroma_me=1 trellis=0 8x8dct=0 cqm=0 deadzone=21,11 fast_pskip=1 chroma_qp_offset=0 threads=1 lookahead_threads=1 sliced_threads=0 nr=0 decimate=1 interlaced=0 bluray_compat=0 constrained_intra=0 bframes=0 weightp=0 keyint=60 keyint_min=25 scenecut=40 intra_refresh=0 rc_lookahead=10 rc=crf mbtree=1 crf=18.0 qcomp=0.60 qpmin=10 qpmax=31 qpstep=4 ip_ratio=1.41 aq=1:1.00
254. 2018-05-27 09:20:25.157478 [INFO] avformat.c:2716 use video codec implementation Video: libx264, yuv420p, 640x480, q=10-31
255. 2018-05-27 09:20:25.167534 [NOTICE] avformat.c:730 video thread start
256. 2018-05-27 09:20:25.247742 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
257. 2018-05-27 09:20:25.247742 [DEBUG] switch_rtp.c:7308 Correct video ip/port confirmed.
258. 2018-05-27 09:20:26.237462 [DEBUG] avcodec.c:1091 picture size changed from 352x288 to 1280x720, reinitializing encoder
259. frame I:1     Avg QP: 3.00  size:  1072
260. mb I  I16..4: 99.7%  0.0%  0.3%
261. coded y,uvDC,uvAC intra: 0.1% 0.0% 0.0%
262. i16 v,h,dc,p: 95%  0%  5%  0%
263. i4 v,h,dc,ddl,ddr,vr,hd,vl,hu:  0%  0% 100%  0%  0%  0%  0%  0%  0%
264. i8c dc,h,v,p: 100%  0%  0%  0%
265. kb/s:771.84
266. using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2
267. profile Constrained Baseline, level 3.1
268. 2018-05-27 09:20:30.397746 [NOTICE] sofia.c:1012 Hangup sofia/internal/353758081570968@192.168.1.97 [CS_EXECUTE] [NORMAL_CLEARING]
269. 2018-05-27 09:20:30.397746 [DEBUG] switch_ivr_bridge.c:726 Ending video thread.
270. 2018-05-27 09:20:30.397746 [DEBUG] switch_ivr_bridge.c:776 Ending video thread.
271. 2018-05-27 09:20:30.397746 [DEBUG] switch_ivr_bridge.c:155 sofia/internal/353758081570968@192.168.1.97 video thread ended.
272. 2018-05-27 09:20:30.397746 [DEBUG] switch_ivr_bridge.c:157 sofia/internal/353758081570968@192.168.1.97 skip receive message [VIDEO_REFRESH_REQ] (channel is hungup already)
273. 2018-05-27 09:20:30.397746 [DEBUG] switch_core_media.c:5970 sofia/internal/353758081570968@192.168.1.97 Video thread ended
274. 2018-05-27 09:20:30.407669 [DEBUG] switch_ivr_bridge.c:726 Ending video thread.
275. 2018-05-27 09:20:30.407669 [DEBUG] switch_ivr_bridge.c:776 Ending video thread.
276. 2018-05-27 09:20:30.407669 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/353758081570968@192.168.1.97]
277. 2018-05-27 09:20:30.407669 [DEBUG] switch_ivr_bridge.c:155 sofia/internal/C8DF84425410@192.168.1.108:5060 video thread ended.
278. 2018-05-27 09:20:30.417722 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/C8DF84425410@192.168.1.108:5060]
279. 2018-05-27 09:20:30.417722 [NOTICE] switch_ivr_bridge.c:904 Hangup sofia/internal/C8DF84425410@192.168.1.108:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
280. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/C8DF84425410@192.168.1.108:5060) State EXCHANGE_MEDIA going to sleep
281. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/C8DF84425410@192.168.1.108:5060) Running State Change CS_HANGUP (Cur 2 Tot 16)
282. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/C8DF84425410@192.168.1.108:5060) Callstate Change ACTIVE -> HANGUP
283. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/C8DF84425410@192.168.1.108:5060) State HANGUP
284. 2018-05-27 09:20:30.417722 [DEBUG] mod_sofia.c:432 sofia/internal/C8DF84425410@192.168.1.108:5060 Overriding SIP cause 480 with 200 from the other leg
285. 2018-05-27 09:20:30.417722 [DEBUG] mod_sofia.c:438 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 hanging up, cause: NORMAL_CLEARING
286. 2018-05-27 09:20:30.417722 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/C8DF84425410@192.168.1.108:5060
287. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:60 sofia/internal/C8DF84425410@192.168.1.108:5060 Standard HANGUP, cause: NORMAL_CLEARING
288. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/C8DF84425410@192.168.1.108:5060) State HANGUP going to sleep
289. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/C8DF84425410@192.168.1.108:5060) State Change CS_HANGUP -> CS_REPORTING
290. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/C8DF84425410@192.168.1.108:5060) Running State Change CS_REPORTING (Cur 2 Tot 16)
291. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/C8DF84425410@192.168.1.108:5060) State REPORTING
292. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:174 sofia/internal/C8DF84425410@192.168.1.108:5060 Standard REPORTING, cause: NORMAL_CLEARING
293. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/C8DF84425410@192.168.1.108:5060) State REPORTING going to sleep
294. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/C8DF84425410@192.168.1.108:5060) State Change CS_REPORTING -> CS_DESTROY
295. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_session.c:1665 Session 16 (sofia/internal/C8DF84425410@192.168.1.108:5060) Locked, Waiting on external entities
296. 2018-05-27 09:20:30.417722 [DEBUG] switch_ivr_bridge.c:1715 sofia/internal/353758081570968@192.168.1.97 skip receive message [UNBRIDGE] (channel is hungup already)
297. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_session.c:2815 sofia/internal/353758081570968@192.168.1.97 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
298. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/353758081570968@192.168.1.97) State EXECUTE going to sleep
299. 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/353758081570968@192.168.1.97) Running State Change CS_HANGUP (Cur 2 Tot 16)
300. 2018-05-27 09:20:30.417722 [DEBUG] switch_ivr_async.c:1316 Stop recording file /var/lib/freeswitch/recordings/WITH_2018-05-27-09-20-24.mp4
301. 2018-05-27 09:20:30.447624 [NOTICE] avformat.c:910 video thread done
302. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_media.c:5970 sofia/internal/C8DF84425410@192.168.1.108:5060 Video thread ended
303. frame I:2     Avg QP:11.38  size: 24194
304. frame P:78    Avg QP:12.64  size:  1017
305. mb I  I16..4: 39.6%  0.0% 60.4%
306. mb P  I16..4:  1.8%  0.0%  0.2%  P16..4:  4.8%  0.5%  0.2%  0.0%  0.0%    skip:92.5%
307. coded y,uvDC,uvAC intra: 77.6% 72.8% 60.9% inter: 2.1% 2.4% 0.9%
308. i16 v,h,dc,p: 22% 20% 44% 14%
309. i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 32% 28% 21%  3%  3%  3%  3%  5%  2%
310. i8c dc,h,v,p: 67% 15% 15%  3%
311. kb/s:193.87
312. 2018-05-27 09:20:30.447624 [DEBUG] switch_ivr_async.c:1380 Channel is hung up
313. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_media_bug.c:1298 Removing BUG from sofia/internal/353758081570968@192.168.1.97
314. 2018-05-27 09:20:30.447624 [NOTICE] switch_core_session.c:1683 Session 16 (sofia/internal/C8DF84425410@192.168.1.108:5060) Ended
315. 2018-05-27 09:20:30.447624 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/C8DF84425410@192.168.1.108:5060 [CS_DESTROY]
316. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/C8DF84425410@192.168.1.108:5060) Running State Change CS_DESTROY (Cur 1 Tot 16)
317. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/C8DF84425410@192.168.1.108:5060) State DESTROY
318. 2018-05-27 09:20:30.447624 [DEBUG] mod_sofia.c:343 sofia/internal/C8DF84425410@192.168.1.108:5060 SOFIA DESTROY
319. frame I:4     Avg QP:15.38  size: 12094
320. frame P:71    Avg QP: 5.84  size:  5204
321. mb I  I16..4: 53.1%  0.0% 46.9%
322. mb P  I16..4:  2.1%  0.0%  0.5%  P16..4: 25.4%  1.4%  0.4%  0.0%  0.0%    skip:70.2%
323. coded y,uvDC,uvAC intra: 55.0% 53.5% 34.9% inter: 12.8% 7.2% 5.3%
324. i16 v,h,dc,p: 21% 27% 34% 19%
325. i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 30% 24% 30%  3%  3%  2%  3%  4%  2%
326. i8c dc,h,v,p: 75% 12% 11%  2%
327. kb/s:4011.39
328. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:181 sofia/internal/C8DF84425410@192.168.1.108:5060 Standard DESTROY
329. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/C8DF84425410@192.168.1.108:5060) State DESTROY going to sleep
330. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/353758081570968@192.168.1.97) Callstate Change ACTIVE -> HANGUP
331. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/353758081570968@192.168.1.97) State HANGUP
332. 2018-05-27 09:20:30.447624 [DEBUG] mod_sofia.c:438 Channel sofia/internal/353758081570968@192.168.1.97 hanging up, cause: NORMAL_CLEARING
333. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:60 sofia/internal/353758081570968@192.168.1.97 Standard HANGUP, cause: NORMAL_CLEARING
334. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/353758081570968@192.168.1.97) State HANGUP going to sleep
335. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/353758081570968@192.168.1.97) State Change CS_HANGUP -> CS_REPORTING
336. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/353758081570968@192.168.1.97) Running State Change CS_REPORTING (Cur 1 Tot 16)
337. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/353758081570968@192.168.1.97) State REPORTING
338. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:174 sofia/internal/353758081570968@192.168.1.97 Standard REPORTING, cause: NORMAL_CLEARING
339. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/353758081570968@192.168.1.97) State REPORTING going to sleep
340. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/353758081570968@192.168.1.97) State Change CS_REPORTING -> CS_DESTROY
341. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_session.c:1665 Session 15 (sofia/internal/353758081570968@192.168.1.97) Locked, Waiting on external entities
342. 2018-05-27 09:20:30.447624 [NOTICE] switch_core_session.c:1683 Session 15 (sofia/internal/353758081570968@192.168.1.97) Ended
343. 2018-05-27 09:20:30.447624 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/353758081570968@192.168.1.97 [CS_DESTROY]
344. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/353758081570968@192.168.1.97) Running State Change CS_DESTROY (Cur 0 Tot 16)
345. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/353758081570968@192.168.1.97) State DESTROY
346. 2018-05-27 09:20:30.447624 [DEBUG] mod_sofia.c:343 sofia/internal/353758081570968@192.168.1.97 SOFIA DESTROY
347. frame I:2     Avg QP:37.60  size: 10576
348. frame P:43    Avg QP:28.52  size:  3907
349. mb I  I16..4: 91.9%  0.0%  8.1%
350. mb P  I16..4:  1.5%  0.0%  0.0%  P16..4: 22.5%  1.4%  0.2%  0.0%  0.0%    skip:74.3%
351. coded y,uvDC,uvAC intra: 15.4% 22.2% 1.3% inter: 6.1% 5.8% 0.0%
352. i16 v,h,dc,p: 42% 26% 25%  7%
353. i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 21% 10% 50%  3%  3%  5%  3%  2%  2%
354. i8c dc,h,v,p: 80%  8% 10%  1%
355. kb/s:3026.37
356. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:181 sofia/internal/353758081570968@192.168.1.97 Standard DESTROY
357. 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/353758081570968@192.168.1.97) State DESTROY going to sleep
358.