2018-05-27 09:20:19.387823 [INFO] mod_pocketsphinx.c:644 PocketSphinx Reloaded 2018-05-27 09:20:19.387823 [INFO] mod_enum.c:879 ENUM Reloaded 2018-05-27 09:20:19.387823 [INFO] switch_time.c:1423 Timezone reloaded 1750 definitions 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] 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) 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 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. 2018-05-27 09:20:24.268069 [DEBUG] sofia.c:2334 detaching session c1345991-1b47-44ba-bd57-baca2ba0b136 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 2018-05-27 09:20:24.268069 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/353758081570968@192.168.1.97) State NEW 2018-05-27 09:20:24.307433 [DEBUG] sofia.c:2442 Re-attaching to session c1345991-1b47-44ba-bd57-baca2ba0b136 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 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. 2018-05-27 09:20:24.317917 [DEBUG] sofia.c:7084 Channel sofia/internal/353758081570968@192.168.1.97 entering state [received][100] 2018-05-27 09:20:24.317917 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=353758081570968 2505 2014 IN IP4 192.168.1.99 s=Talk c=IN IP4 192.168.1.99 t=0 0 a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics m=audio 7078 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=rtcp-fb:* trr-int 5000 a=rtcp-fb:* ccm tmmbr m=video 9078 RTP/AVP 96 a=rtpmap:96 H264/90000 a=fmtp:96 profile-level-id=42801F a=rtcp-fb:* trr-int 5000 a=rtcp-fb:* ccm tmmbr a=rtcp-fb:96 nack pli a=rtcp-fb:96 ccm fir 2018-05-27 09:20:24.317917 [DEBUG] sofia.c:7486 (sofia/internal/353758081570968@192.168.1.97) State Change CS_NEW -> CS_INIT 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) 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/353758081570968@192.168.1.97) State INIT 2018-05-27 09:20:24.317917 [DEBUG] mod_sofia.c:90 sofia/internal/353758081570968@192.168.1.97 SOFIA INIT 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:40 sofia/internal/353758081570968@192.168.1.97 Standard INIT 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 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 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) 2018-05-27 09:20:24.317917 [DEBUG] switch_channel.c:2249 (sofia/internal/353758081570968@192.168.1.97) Callstate Change DOWN -> RINGING 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/353758081570968@192.168.1.97) State ROUTING 2018-05-27 09:20:24.317917 [DEBUG] mod_sofia.c:143 sofia/internal/353758081570968@192.168.1.97 SOFIA ROUTING 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:236 sofia/internal/353758081570968@192.168.1.97 Standard ROUTING 2018-05-27 09:20:24.317917 [INFO] mod_dialplan_xml.c:637 Processing 353758081570968 <353758081570968>->C8DF84425410 in context default Dialplan: sofia/internal/353758081570968@192.168.1.97 parsing [default->C8DF84425410] continue=false Dialplan: sofia/internal/353758081570968@192.168.1.97 Regex (PASS) [C8DF84425410] destination_number(C8DF84425410) =~ /^(([0-9a-fA-F]){12})$/ break=on-false Dialplan: sofia/internal/353758081570968@192.168.1.97 Action export(dialed_extension=C8DF84425410) Dialplan: sofia/internal/353758081570968@192.168.1.97 Action set(enable_file_write_buffering=false) Dialplan: sofia/internal/353758081570968@192.168.1.97 Action set(RECORD_STEREO=true) 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) Dialplan: sofia/internal/353758081570968@192.168.1.97 Action bridge(user/${dialed_extension}@${domain_name}) 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 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 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) 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/353758081570968@192.168.1.97) State EXECUTE 2018-05-27 09:20:24.317917 [DEBUG] mod_sofia.c:198 sofia/internal/353758081570968@192.168.1.97 SOFIA EXECUTE 2018-05-27 09:20:24.317917 [DEBUG] switch_core_state_machine.c:328 sofia/internal/353758081570968@192.168.1.97 Standard EXECUTE EXECUTE sofia/internal/353758081570968@192.168.1.97 export(dialed_extension=C8DF84425410) 2018-05-27 09:20:24.317917 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[C8DF84425410] EXECUTE sofia/internal/353758081570968@192.168.1.97 set(enable_file_write_buffering=false) 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] EXECUTE sofia/internal/353758081570968@192.168.1.97 set(RECORD_STEREO=true) 2018-05-27 09:20:24.317917 [DEBUG] mod_dptools.c:1548 SET sofia/internal/353758081570968@192.168.1.97 [RECORD_STEREO]=[true] 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) 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] EXECUTE sofia/internal/353758081570968@192.168.1.97 bridge(user/C8DF84425410@192.168.1.97) 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 2018-05-27 09:20:24.317917 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 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 2018-05-27 09:20:24.327396 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 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] 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 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) 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/C8DF84425410@192.168.1.108:5060) State INIT 2018-05-27 09:20:24.327396 [DEBUG] mod_sofia.c:90 sofia/internal/C8DF84425410@192.168.1.108:5060 SOFIA INIT 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 Local SDP: v=0 o=FreeSWITCH 1527401382 1527401383 IN IP4 192.168.1.97 s=FreeSWITCH c=IN IP4 192.168.1.97 t=0 0 m=audio 25842 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 30732 RTP/AVP 96 b=AS:1024 a=rtpmap:96 H264/90000 a=fmtp:96 profile-level-id=42801F a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:40 sofia/internal/C8DF84425410@192.168.1.108:5060 Standard INIT 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 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 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) 2018-05-27 09:20:24.327396 [DEBUG] sofia.c:7084 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 entering state [calling][0] 2018-05-27 09:20:24.327396 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/C8DF84425410@192.168.1.108:5060) State ROUTING 2018-05-27 09:20:24.327396 [DEBUG] mod_sofia.c:143 sofia/internal/C8DF84425410@192.168.1.108:5060 SOFIA ROUTING 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 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 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) 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 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 2018-05-27 09:20:24.517932 [DEBUG] sofia.c:7084 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 entering state [proceeding][180] 2018-05-27 09:20:24.517932 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/C8DF84425410@192.168.1.108:5060! 2018-05-27 09:20:24.517932 [DEBUG] switch_channel.c:3346 (sofia/internal/C8DF84425410@192.168.1.108:5060) Callstate Change DOWN -> RINGING 2018-05-27 09:20:24.517932 [DEBUG] sofia.c:7084 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 entering state [completing][200] 2018-05-27 09:20:24.517932 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=C8DF84425410 0 0 IN IP4 192.168.1.108 c=IN IP4 192.168.1.108 t=0 0 m=audio 9002 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 m=video 9000 RTP/AVP 96 a=rtpmap:96 H264/90000 a=fmtp:96 packetization-mode=1;profile-level-id=42801f;sprop-parameter-sets=Z0IAH52oFAFum4CAgIE=,aM48gA==; a=sendonly 2018-05-27 09:20:24.517932 [DEBUG] sofia.c:7084 Channel sofia/internal/C8DF84425410@192.168.1.108:5060 entering state [ready][200] 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] 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 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 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 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 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 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 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4950 Video Codec Compare [H264:96]/[H264:99] 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4993 No matches with FTMP, fallback to ignoring FMTP 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4950 Video Codec Compare [H264:96]/[H264:99] 2018-05-27 09:20:24.517932 [DEBUG] switch_core_media.c:4982 Video Codec Compare [H264:96] +++ is saved as a match 2018-05-27 09:20:24.517932 [NOTICE] avcodec.c:1022 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 2018-05-27 09:20:24.517932 [NOTICE] avcodec.c:1022 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 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 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 2018-05-27 09:20:24.527777 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms 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 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 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 2018-05-27 09:20:24.527777 [DEBUG] switch_rtp.c:4152 Starting video timer. 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] 2018-05-27 09:20:24.527777 [DEBUG] switch_core_media.c:6003 sofia/internal/C8DF84425410@192.168.1.108:5060 Starting Video thread 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 2018-05-27 09:20:24.527777 [NOTICE] sofia.c:8218 Channel [sofia/internal/C8DF84425410@192.168.1.108:5060] has been answered 2018-05-27 09:20:24.527777 [DEBUG] switch_channel.c:3773 (sofia/internal/C8DF84425410@192.168.1.108:5060) Callstate Change RINGING -> ACTIVE 2018-05-27 09:20:24.538220 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/internal/353758081570968@192.168.1.97! 2018-05-27 09:20:24.538220 [DEBUG] sofia.c:7084 Channel sofia/internal/353758081570968@192.168.1.97 entering state [early][180] 2018-05-27 09:20:24.538220 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/internal/353758081570968@192.168.1.97! 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] 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 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 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 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 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 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 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4950 Video Codec Compare [H264:96]/[H264:99] 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:4982 Video Codec Compare [H264:96] +++ is saved as a match 2018-05-27 09:20:24.538220 [NOTICE] avcodec.c:1022 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 2018-05-27 09:20:24.538220 [NOTICE] avcodec.c:1022 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 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 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 2018-05-27 09:20:24.538220 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms 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 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 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 2018-05-27 09:20:24.538220 [DEBUG] switch_rtp.c:4152 Starting video timer. 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] 2018-05-27 09:20:24.538220 [DEBUG] switch_core_media.c:6003 sofia/internal/353758081570968@192.168.1.97 Starting Video thread 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 2018-05-27 09:20:24.538220 [INFO] switch_core_media.c:7479 Activating VIDEO RTCP PORT 9079 interval 1000 mux -1 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 2018-05-27 09:20:24.538220 [DEBUG] switch_rtp.c:2567 Setting RTCP remote addr to 192.168.1.99:9079 2 2018-05-27 09:20:24.538220 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/353758081570968@192.168.1.97! 2018-05-27 09:20:24.538220 [DEBUG] switch_channel.c:3474 (sofia/internal/353758081570968@192.168.1.97) Callstate Change RINGING -> EARLY 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. 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. 2018-05-27 09:20:24.538220 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/353758081570968@192.168.1.97: v=0 o=FreeSWITCH 1527403908 1527403909 IN IP4 192.168.1.97 s=FreeSWITCH c=IN IP4 192.168.1.97 t=0 0 m=audio 23316 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 29112 RTP/AVP 96 b=AS:1024 a=rtpmap:96 H264/90000 a=fmtp:96 profile-level-id=42801F a=rtcp:29113 IN IP4 192.168.1.97 a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli 2018-05-27 09:20:24.547680 [DEBUG] sofia.c:7084 Channel sofia/internal/353758081570968@192.168.1.97 entering state [completed][200] 2018-05-27 09:20:24.547680 [NOTICE] switch_ivr_originate.c:3647 Channel [sofia/internal/353758081570968@192.168.1.97] has been answered EXECUTE sofia/internal/353758081570968@192.168.1.97 record_session(/var/lib/freeswitch/recordings/WITH_2018-05-27-09-20-24.mp4) 2018-05-27 09:20:24.547680 [DEBUG] avformat.c:1919 sample rate: 8000, channels: 2 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) 2018-05-27 09:20:24.547680 [NOTICE] avformat.c:648 sample_rate: 8000 nb_samples: 1024 Output #0, mp4, to '/var/lib/freeswitch/recordings/WITH_2018-05-27-09-20-24.mp4': Stream #0.0 : Audio: libvo_aacenc, 8000 Hz, stereo, s16, 131 kb/s 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 2018-05-27 09:20:24.558509 [DEBUG] switch_core_media_bug.c:945 Attaching BUG to sofia/internal/353758081570968@192.168.1.97 2018-05-27 09:20:24.558509 [DEBUG] switch_channel.c:3773 (sofia/internal/353758081570968@192.168.1.97) Callstate Change EARLY -> ACTIVE 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] 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] 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 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) 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 2018-05-27 09:20:24.558509 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA 2018-05-27 09:20:24.558509 [DEBUG] switch_ivr_async.c:1500 No silence detection configured; assuming start of speech 2018-05-27 09:20:24.617540 [DEBUG] sofia.c:7084 Channel sofia/internal/353758081570968@192.168.1.97 entering state [ready][200] 2018-05-27 09:20:24.628405 [INFO] avcodec.c:1083 initializing encoder 352x288 2018-05-27 09:20:24.628405 [DEBUG] avcodec.c:832 NVENC HW CODEC NOT PRESENT using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2 profile Constrained Baseline, level 3.1 2018-05-27 09:20:24.647572 [INFO] avcodec.c:1083 initializing encoder 352x288 2018-05-27 09:20:24.647572 [DEBUG] avcodec.c:832 NVENC HW CODEC NOT PRESENT using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2 profile Constrained Baseline, level 3.1 2018-05-27 09:20:24.657543 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed. 2018-05-27 09:20:24.657543 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0 2018-05-27 09:20:24.807552 [DEBUG] switch_rtp.c:6758 Correct video RTCP ip/port confirmed. 2018-05-27 09:20:25.018159 [DEBUG] switch_rtp.c:1887 rtcp_stats_init: video ssrc[3354518260] base_seq[0] 2018-05-27 09:20:25.077544 [DEBUG] switch_rtp.c:7308 Correct video ip/port confirmed. 2018-05-27 09:20:25.087508 [DEBUG] avcodec.c:1091 picture size changed from 352x288 to 640x480, reinitializing encoder frame I:1 Avg QP: 3.00 size: 1072 mb I I16..4: 99.7% 0.0% 0.3% coded y,uvDC,uvAC intra: 0.1% 0.0% 0.0% i16 v,h,dc,p: 95% 0% 5% 0% i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 0% 0% 100% 0% 0% 0% 0% 0% 0% i8c dc,h,v,p: 100% 0% 0% 0% kb/s:771.84 using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2 profile Constrained Baseline, level 3.1 using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2 profile Constrained Baseline, level 4.1 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 2018-05-27 09:20:25.157478 [INFO] avformat.c:2716 use video codec implementation Video: libx264, yuv420p, 640x480, q=10-31 2018-05-27 09:20:25.167534 [NOTICE] avformat.c:730 video thread start 2018-05-27 09:20:25.247742 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed. 2018-05-27 09:20:25.247742 [DEBUG] switch_rtp.c:7308 Correct video ip/port confirmed. 2018-05-27 09:20:26.237462 [DEBUG] avcodec.c:1091 picture size changed from 352x288 to 1280x720, reinitializing encoder frame I:1 Avg QP: 3.00 size: 1072 mb I I16..4: 99.7% 0.0% 0.3% coded y,uvDC,uvAC intra: 0.1% 0.0% 0.0% i16 v,h,dc,p: 95% 0% 5% 0% i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 0% 0% 100% 0% 0% 0% 0% 0% 0% i8c dc,h,v,p: 100% 0% 0% 0% kb/s:771.84 using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX AVX2 FMA3 LZCNT BMI2 profile Constrained Baseline, level 3.1 2018-05-27 09:20:30.397746 [NOTICE] sofia.c:1012 Hangup sofia/internal/353758081570968@192.168.1.97 [CS_EXECUTE] [NORMAL_CLEARING] 2018-05-27 09:20:30.397746 [DEBUG] switch_ivr_bridge.c:726 Ending video thread. 2018-05-27 09:20:30.397746 [DEBUG] switch_ivr_bridge.c:776 Ending video thread. 2018-05-27 09:20:30.397746 [DEBUG] switch_ivr_bridge.c:155 sofia/internal/353758081570968@192.168.1.97 video thread ended. 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) 2018-05-27 09:20:30.397746 [DEBUG] switch_core_media.c:5970 sofia/internal/353758081570968@192.168.1.97 Video thread ended 2018-05-27 09:20:30.407669 [DEBUG] switch_ivr_bridge.c:726 Ending video thread. 2018-05-27 09:20:30.407669 [DEBUG] switch_ivr_bridge.c:776 Ending video thread. 2018-05-27 09:20:30.407669 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/353758081570968@192.168.1.97] 2018-05-27 09:20:30.407669 [DEBUG] switch_ivr_bridge.c:155 sofia/internal/C8DF84425410@192.168.1.108:5060 video thread ended. 2018-05-27 09:20:30.417722 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/C8DF84425410@192.168.1.108:5060] 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] 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 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) 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 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/C8DF84425410@192.168.1.108:5060) State HANGUP 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 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 2018-05-27 09:20:30.417722 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/C8DF84425410@192.168.1.108:5060 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 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 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 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) 2018-05-27 09:20:30.417722 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/C8DF84425410@192.168.1.108:5060) State REPORTING 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 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 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 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 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) 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) 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 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) 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 2018-05-27 09:20:30.447624 [NOTICE] avformat.c:910 video thread done 2018-05-27 09:20:30.447624 [DEBUG] switch_core_media.c:5970 sofia/internal/C8DF84425410@192.168.1.108:5060 Video thread ended frame I:2 Avg QP:11.38 size: 24194 frame P:78 Avg QP:12.64 size: 1017 mb I I16..4: 39.6% 0.0% 60.4% 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% coded y,uvDC,uvAC intra: 77.6% 72.8% 60.9% inter: 2.1% 2.4% 0.9% i16 v,h,dc,p: 22% 20% 44% 14% i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 32% 28% 21% 3% 3% 3% 3% 5% 2% i8c dc,h,v,p: 67% 15% 15% 3% kb/s:193.87 2018-05-27 09:20:30.447624 [DEBUG] switch_ivr_async.c:1380 Channel is hung up 2018-05-27 09:20:30.447624 [DEBUG] switch_core_media_bug.c:1298 Removing BUG from sofia/internal/353758081570968@192.168.1.97 2018-05-27 09:20:30.447624 [NOTICE] switch_core_session.c:1683 Session 16 (sofia/internal/C8DF84425410@192.168.1.108:5060) Ended 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] 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) 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/C8DF84425410@192.168.1.108:5060) State DESTROY 2018-05-27 09:20:30.447624 [DEBUG] mod_sofia.c:343 sofia/internal/C8DF84425410@192.168.1.108:5060 SOFIA DESTROY frame I:4 Avg QP:15.38 size: 12094 frame P:71 Avg QP: 5.84 size: 5204 mb I I16..4: 53.1% 0.0% 46.9% 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% coded y,uvDC,uvAC intra: 55.0% 53.5% 34.9% inter: 12.8% 7.2% 5.3% i16 v,h,dc,p: 21% 27% 34% 19% i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 30% 24% 30% 3% 3% 2% 3% 4% 2% i8c dc,h,v,p: 75% 12% 11% 2% kb/s:4011.39 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:181 sofia/internal/C8DF84425410@192.168.1.108:5060 Standard DESTROY 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 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 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/353758081570968@192.168.1.97) State HANGUP 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 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 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 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 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) 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/353758081570968@192.168.1.97) State REPORTING 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 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 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 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 2018-05-27 09:20:30.447624 [NOTICE] switch_core_session.c:1683 Session 15 (sofia/internal/353758081570968@192.168.1.97) Ended 2018-05-27 09:20:30.447624 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/353758081570968@192.168.1.97 [CS_DESTROY] 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) 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/353758081570968@192.168.1.97) State DESTROY 2018-05-27 09:20:30.447624 [DEBUG] mod_sofia.c:343 sofia/internal/353758081570968@192.168.1.97 SOFIA DESTROY frame I:2 Avg QP:37.60 size: 10576 frame P:43 Avg QP:28.52 size: 3907 mb I I16..4: 91.9% 0.0% 8.1% 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% coded y,uvDC,uvAC intra: 15.4% 22.2% 1.3% inter: 6.1% 5.8% 0.0% i16 v,h,dc,p: 42% 26% 25% 7% i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 21% 10% 50% 3% 3% 5% 3% 2% 2% i8c dc,h,v,p: 80% 8% 10% 1% kb/s:3026.37 2018-05-27 09:20:30.447624 [DEBUG] switch_core_state_machine.c:181 sofia/internal/353758081570968@192.168.1.97 Standard DESTROY 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