search

signalwire / freeswitch

FreeSWITCH is a Software Defined Telecom Stack enabling the digital transformation from proprietary telecom switches to a versatile software implementation that runs on any commodity hardware. From a Raspberry PI to a multi-core server, FreeSWITCH can unlock the telecommunications potential of any device.
https://freeswitch.com/#getting-started
Other
3.56k stars 1.41k forks source link

Video delay using WebRTC with bridge - no delay with conference #893

Closed tinpotnick closed 4 years ago

tinpotnick commented 4 years ago

Describe the bug When a call is initiated from one web client to another using bridge (across a different profile) in one direction you get a progressively worse delay in video. When using a conference room in FS - the quality is perfect.

To Reproduce Steps to reproduce the behavior:

  1. Use jssip for a webapp with video, one client in internal profile, another in guest profile
  2. Call guest profile from internal using bridge
  3. wait 30 seconds to see delay getting worse
  4. Perform the same call but using a conference facility and there is no delay

Expected behavior

No delay

Package version or git hash FreeSWITCH Version 1.10.5-release-17-25569c1631~64bit (-release-17-25569c1631 64bit)

Trace logs 2020-10-08 11:41:00.860114 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1001@bling.babblevoice.com [c5ac2593-ab39-4d81-9844-d87533ef8a18] 2020-10-08 11:41:00.860114 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1001@bling.babblevoice.com) Running State Change CS_NEW (Cur 1 Tot 498) 2020-10-08 11:41:00.860114 [DEBUG] sofia.c:10280 sofia/internal/1001@bling.babblevoice.com receiving invite from 82.19.206.102:38538 version: 1.10.5 -release-17-25569c1631 64bit 2020-10-08 11:41:00.860114 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port 82.19.206.102:0. 2020-10-08 11:41:00.860114 [WARNING] sofia_reg.c:1794 SIP auth challenge (INVITE) on sofia profile 'internal' for [*82040412@bling.babblevoice.com] from ip 82.19.206.102 2020-10-08 11:41:00.860114 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/1001@bling.babblevoice.com) State NEW 2020-10-08 11:41:00.860114 [DEBUG] sofia.c:2434 detaching session c5ac2593-ab39-4d81-9844-d87533ef8a18 2020-10-08 11:41:00.900114 [DEBUG] sofia.c:2544 Re-attaching to session c5ac2593-ab39-4d81-9844-d87533ef8a18 2020-10-08 11:41:00.900114 [DEBUG] sofia.c:10280 sofia/internal/1001@bling.babblevoice.com receiving invite from 82.19.206.102:38538 version: 1.10.5 -release-17-25569c1631 64bit 2020-10-08 11:41:00.900114 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port 82.19.206.102:0. 2020-10-08 11:41:00.920118 [DEBUG] sofia.c:11477 Setting NAT mode based on via received 2020-10-08 11:41:00.920118 [DEBUG] sofia.c:7326 Channel sofia/internal/1001@bling.babblevoice.com entering state [received][100] 2020-10-08 11:41:00.920118 [DEBUG] sofia.c:7333 Duplicate SDP v=0 o=- 6585167870088634420 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE 0 1 a=msid-semantic: WMS VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ m=audio 43155 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 82.19.206.102 a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:842238307 1 udp 2122260223 192.168.0.141 43155 typ host generation 0 network-id 1 network-cost 10 a=candidate:3011219415 1 udp 1686052607 82.19.206.102 43155 typ srflx raddr 192.168.0.141 rport 43155 generation 0 network-id 1 network-cost 10 a=ice-ufrag:1xJ3 a=ice-pwd:aYW6jyFX88qBwEkPsduwRUxQ a=ice-options:trickle a=fingerprint:sha-256 08:D9:35:F7:AC:2B:7E:BD:89:27:24:91:74:34:16:5D:07:BB:46:A0:26:39:82:C8:9F:63:B8:51:C1:18:93:00 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ 2e3a4eb8-e3a1-4c61-bb5c-164071540f67 a=rtcp-mux a=rtcp-fb:111 transport-cc a=ssrc:2927645597 cname:VpLzLmnssiK7E9MK a=ssrc:2927645597 msid:VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ 2e3a4eb8-e3a1-4c61-bb5c-164071540f67 a=ssrc:2927645597 mslabel:VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ a=ssrc:2927645597 label:2e3a4eb8-e3a1-4c61-bb5c-164071540f67 m=video 39515 UDP/TLS/RTP/SAVPF 96 97 98 99 100 101 102 121 127 120 125 107 108 109 124 119 123 c=IN IP4 82.19.206.102 a=rtpmap:96 VP8/90000 a=rtpmap:97 rtx/90000 a=fmtp:97 apt=96 a=rtpmap:98 VP9/90000 a=fmtp:98 profile-id=0 a=rtpmap:99 rtx/90000 a=fmtp:99 apt=98 a=rtpmap:100 VP9/90000 a=fmtp:100 profile-id=2 a=rtpmap:101 rtx/90000 a=fmtp:101 apt=100 a=rtpmap:102 H264/90000 a=fmtp:102 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42001f a=rtpmap:121 rtx/90000 a=fmtp:121 apt=102 a=rtpmap:127 H264/90000 a=fmtp:127 level-asymmetry-allowed=1;packetization-mode=0;profile-level-id=42001f a=rtpmap:120 rtx/90000 a=fmtp:120 apt=127 a=rtpmap:125 H264/90000 a=fmtp:125 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f a=rtpmap:107 rtx/90000 a=fmtp:107 apt=125 a=rtpmap:108 H264/90000 a=fmtp:108 level-asymmetry-allowed=1;packetization-mode=0;profile-level-id=42e01f a=rtpmap:109 rtx/90000 a=fmtp:109 apt=108 a=rtpmap:124 red/90000 a=rtpmap:119 rtx/90000 a=fmtp:119 apt=124 a=rtpmap:123 ulpfec/90000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:842238307 1 udp 2122260223 192.168.0.141 39515 typ host generation 0 network-id 1 network-cost 10 a=candidate:3011219415 1 udp 1686052607 82.19.206.102 39515 typ srflx raddr 192.168.0.141 rport 39515 generation 0 network-id 1 network-cost 10 a=ice-ufrag:1xJ3 a=ice-pwd:aYW6jyFX88qBwEkPsduwRUxQ a=ice-options:trickle a=fingerprint:sha-256 08:D9:35:F7:AC:2B:7E:BD:89:27:24:91:74:34:16:5D:07:BB:46:A0:26:39:82:C8:9F:63:B8:51:C1:18:93:00 a=setup:actpass a=mid:1 a=extmap:14 urn:ietf:params:rtp-hdrext:toffset a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time a=extmap:13 urn:3gpp:video-orientation a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:12 http://www.webrtc.org/experiments/rtp-hdrext/playout-delay a=extmap:11 http://www.webrtc.org/experiments/rtp-hdrext/video-content-type a=extmap:7 http://www.webrtc.org/experiments/rtp-hdrext/video-timing a=extmap:8 http://www.webrtc.org/experiments/rtp-hdrext/color-space a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ 0de87433-a963-45ab-83ba-d953746fbfb4 a=rtcp-mux a=rtcp-rsize a=rtcp-fb:96 goog-remb a=rtcp-fb:96 transport-cc a=rtcp-fb:96 ccm fir a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=rtcp-fb:98 goog-remb a=rtcp-fb:98 transport-cc a=rtcp-fb:98 ccm fir a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=rtcp-fb:100 goog-remb a=rtcp-fb:100 transport-cc a=rtcp-fb:100 ccm fir a=rtcp-fb:100 nack a=rtcp-fb:100 nack pli a=rtcp-fb:102 goog-remb a=rtcp-fb:102 transport-cc a=rtcp-fb:102 ccm fir a=rtcp-fb:102 nack a=rtcp-fb:102 nack pli a=rtcp-fb:127 goog-remb a=rtcp-fb:127 transport-cc a=rtcp-fb:127 ccm fir a=rtcp-fb:127 nack a=rtcp-fb:127 nack pli a=rtcp-fb:125 goog-remb a=rtcp-fb:125 transport-cc a=rtcp-fb:125 ccm fir a=rtcp-fb:125 nack a=rtcp-fb:125 nack pli a=rtcp-fb:108 goog-remb a=rtcp-fb:108 transport-cc a=rtcp-fb:108 ccm fir a=rtcp-fb:108 nack a=rtcp-fb:108 nack pli a=ssrc-group:FID 2140772957 1123417960 a=ssrc:2140772957 cname:VpLzLmnssiK7E9MK a=ssrc:2140772957 msid:VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ 0de87433-a963-45ab-83ba-d953746fbfb4 a=ssrc:2140772957 mslabel:VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ a=ssrc:2140772957 label:0de87433-a963-45ab-83ba-d953746fbfb4 a=ssrc:1123417960 cname:VpLzLmnssiK7E9MK a=ssrc:1123417960 msid:VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ 0de87433-a963-45ab-83ba-d953746fbfb4 a=ssrc:1123417960 mslabel:VFA8LvPBqKRp7tusuZNvWUuxDmSxCwqffUCZ a=ssrc:1123417960 label:0de87433-a963-45ab-83ba-d953746fbfb4

2020-10-08 11:41:00.920118 [DEBUG] sofia.c:7739 (sofia/internal/1001@bling.babblevoice.com) State Change CS_NEW -> CS_INIT 2020-10-08 11:41:00.920118 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1001@bling.babblevoice.com) Running State Change CS_INIT (Cur 1 Tot 498) 2020-10-08 11:41:00.920118 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1001@bling.babblevoice.com) State INIT 2020-10-08 11:41:00.920118 [DEBUG] mod_sofia.c:93 sofia/internal/1001@bling.babblevoice.com SOFIA INIT 2020-10-08 11:41:00.920118 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@bling.babblevoice.com Standard INIT 2020-10-08 11:41:00.920118 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@bling.babblevoice.com) State Change CS_INIT -> CS_ROUTING 2020-10-08 11:41:00.920118 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1001@bling.babblevoice.com) State INIT going to sleep 2020-10-08 11:41:00.940412 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1001@bling.babblevoice.com) Running State Change CS_ROUTING (Cur 1 Tot 498) 2020-10-08 11:41:00.940412 [DEBUG] switch_channel.c:2332 (sofia/internal/1001@bling.babblevoice.com) Callstate Change DOWN -> RINGING 2020-10-08 11:41:00.940412 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1001@bling.babblevoice.com) State ROUTING 2020-10-08 11:41:00.940412 [DEBUG] mod_sofia.c:154 sofia/internal/1001@bling.babblevoice.com SOFIA ROUTING 2020-10-08 11:41:00.940412 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1001@bling.babblevoice.com Standard ROUTING 2020-10-08 11:41:00.940412 [INFO] mod_dialplan_xml.c:637 Processing 1001 <1001>->82040412 in context default Dialplan: sofia/internal/1001@bling.babblevoice.com parsing [default->unloop] continue=false Dialplan: sofia/internal/1001@bling.babblevoice.com Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1001@bling.babblevoice.com Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1001@bling.babblevoice.com parsing [default->refer] continue=false Dialplan: sofia/internal/1001@bling.babblevoice.com Regex (FAIL) [refer] ${sip_refer_to}() =~ /<sip:(.)@(.)>/ break=on-false Dialplan: sofia/internal/1001@bling.babblevoice.com parsing [default->global-internal] continue=false Dialplan: sofia/internal/1001@bling.babblevoice.com Regex (PASS) [global-internal] destination_number(82040412) =~ /^([a-zA-Z0-9*#]+)$/ break=on-false Dialplan: sofia/internal/1001@bling.babblevoice.com Action lua(internal.lua) 2020-10-08 11:41:00.940412 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/1001@bling.babblevoice.com) State Change CS_ROUTING -> CS_EXECUTE 2020-10-08 11:41:00.940412 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1001@bling.babblevoice.com) State ROUTING going to sleep 2020-10-08 11:41:00.940412 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1001@bling.babblevoice.com) Running State Change CS_EXECUTE (Cur 1 Tot 498) 2020-10-08 11:41:00.940412 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1001@bling.babblevoice.com) State EXECUTE 2020-10-08 11:41:00.940412 [DEBUG] mod_sofia.c:209 sofia/internal/1001@bling.babblevoice.com SOFIA EXECUTE 2020-10-08 11:41:00.940412 [DEBUG] switch_core_state_machine.c:329 sofia/internal/1001@bling.babblevoice.com Standard EXECUTE EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com lua(internal.lua) 2020-10-08 11:41:00.960124 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('api_hangup_hook', 'lua onhangup.lua') 2020-10-08 11:41:00.960124 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_aleg', 'true') 2020-10-08 11:41:00.960124 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('execute_on_answer', 'lua onanswer.lua ${uuid}') 2020-10-08 11:41:00.960124 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('send_silence_when_idle', 'true') 2020-10-08 11:41:00.960124 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('bridge_generate_comfort_noise', 'true') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(rtp_auto_adjust_threshold=1) 2020-10-08 11:41:00.960124 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [rtp_auto_adjust_threshold]=[1] EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(sip_redirect_context=default) 2020-10-08 11:41:00.960124 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [sip_redirect_context]=[default] 2020-10-08 11:41:00.960124 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('api_reporting_hook', 'lua onreporting.lua') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com unset(sip_h_X-CALLINFO) 2020-10-08 11:41:00.960124 [DEBUG] mod_dptools.c:1817 UNSET [sip_h_X-CALLINFO] EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com unset(X-Serialnumber) 2020-10-08 11:41:00.960124 [DEBUG] mod_dptools.c:1817 UNSET [X-Serialnumber] EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(sip_invite_domain=bling.babblevoice.com) 2020-10-08 11:41:00.960124 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [sip_invite_domain]=[bling.babblevoice.com] EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(sip_auth_realm=bling.babblevoice.com) 2020-10-08 11:41:00.960124 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [sip_auth_realm]=[bling.babblevoice.com] 2020-10-08 11:41:00.960124 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_call_aleg_realm', 'bling.babblevoice.com') 2020-10-08 11:41:00.960124 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('hold_music', '/tmp/prompt_9263bd36-7a8e-11e6-b03a-22000a2293e8.wav') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(hold_music=/tmp/prompt_9263bd36-7a8e-11e6-b03a-22000a2293e8.wav) 2020-10-08 11:41:00.960124 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [hold_music]=[/tmp/prompt_9263bd36-7a8e-11e6-b03a-22000a2293e8.wav] EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(sip_authorized=true) 2020-10-08 11:41:00.980121 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [sip_authorized]=[true] 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_local_from_realm', 'bling.babblevoice.com') 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_local_from_user', '1001') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(babble_local_call_initiated_by=1001@bling.babblevoice.com) 2020-10-08 11:41:00.980121 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [babble_local_call_initiated_by]=[1001@bling.babblevoice.com] EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com fifo_track_call(e81c38f0dfd108b55b9e0fe1278b3dc8) 2020-10-08 11:41:00.980121 [DEBUG] mod_fifo.c:2481 sofia/internal/1001@bling.babblevoice.com tracking call on uuid e81c38f0dfd108b55b9e0fe1278b3dc8! 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('sip_to_host', 'bling.babblevoice.com') 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('sip_to_user', '*82040412') 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('sip_from_host', 'bling.babblevoice.com') 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('nibble_account', '417') 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('accountcode', '417') 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('nibble_interval', 'second') 2020-10-08 11:41:00.980121 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('force_transfer_context', 'default') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('absolute_codec_string', 'G722,PCMA,iLBC') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('recorded', '0') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_recording', 'false') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('RECORD_STEREO', 'true') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('recording_follow_transfer', 'true') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('recording_follow_attxfer', 'true') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_callrecording_format', 'mp3') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('recorded', '1') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_recording', 'true') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('ringback', '%(400,200,400,450);%(400,2200,400,450)') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com set(RECORD_COPYRIGHT=(c) babblevoice 2020) 2020-10-08 11:41:01.000133 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1001@bling.babblevoice.com [RECORD_COPYRIGHT]=[(c) babblevoice 2020] 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('RECORD_SOFTWARE', 'babblevoice') 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('RECORD_ARTIST', 'Unknown') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com set(RECORD_DATE=2020-10-08 11:41) 2020-10-08 11:41:01.000133 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1001@bling.babblevoice.com [RECORD_DATE]=[2020-10-08 11:41] 2020-10-08 11:41:01.000133 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_callrecording_filename', '/tmp/c5ac2593-ab39-4d81-9844-d87533ef8a18.wav') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(babble_callrecording_filename=/tmp/c5ac2593-ab39-4d81-9844-d87533ef8a18.wav) 2020-10-08 11:41:01.000133 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [babble_callrecording_filename]=[/tmp/c5ac2593-ab39-4d81-9844-d87533ef8a18.wav] 2020-10-08 11:41:01.020147 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_callrecording_uuid', 'c5ac2593-ab39-4d81-9844-d87533ef8a18') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(babble_callrecording_uuid=c5ac2593-ab39-4d81-9844-d87533ef8a18) 2020-10-08 11:41:01.020147 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [babble_callrecording_uuid]=[c5ac2593-ab39-4d81-9844-d87533ef8a18] 2020-10-08 11:41:01.020147 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_callrecording_accountcode', '417') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com export(babble_callrecording_accountcode=417) 2020-10-08 11:41:01.020147 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [babble_callrecording_accountcode]=[417] 2020-10-08 11:41:01.040118 [NOTICE] switch_cpp.cpp:1447 Adding Video bv-desktop-jssip_chrome_85 2020-10-08 11:41:01.040118 [NOTICE] switch_cpp.cpp:1447 To G722,PCMA,iLBC 2020-10-08 11:41:01.040118 [NOTICE] switch_cpp.cpp:1447 No VP8... adding 2020-10-08 11:41:01.040118 [NOTICE] switch_cpp.cpp:1447 New CODEC string VP8,G722,PCMA,iLBC 2020-10-08 11:41:01.040118 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('absolute_codec_string', 'VP8,G722,PCMA,iLBC') 2020-10-08 11:41:01.060120 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('continue_on_fail', 'USER_NOT_REGISTERED,NORMAL_TEMPORARY_FAILURE,USER_BUSY,NO_ANSWER,NO_ROUTE_DESTINATION,NO_USER_RESPONSE,INCOMPATIBLE_DESTINATION') 2020-10-08 11:41:01.060120 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('babble_aleg', 'true') EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com bridge(user/82040412@bling.babblevoice.com) 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [rtp_auto_adjust_threshold]=[1] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [sip_redirect_context]=[default] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [sip_invite_domain]=[bling.babblevoice.com] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [sip_auth_realm]=[bling.babblevoice.com] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [hold_music]=[/tmp/prompt_9263bd36-7a8e-11e6-b03a-22000a2293e8.wav] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [sip_authorized]=[true] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [babble_local_call_initiated_by]=[1001@bling.babblevoice.com] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [babble_callrecording_filename]=[/tmp/c5ac2593-ab39-4d81-9844-d87533ef8a18.wav] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [babble_callrecording_uuid]=[c5ac2593-ab39-4d81-9844-d87533ef8a18] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [babble_callrecording_accountcode]=[417] to event 2020-10-08 11:41:01.060120 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [rtp_auto_adjust_threshold]=[1] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [sip_redirect_context]=[default] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [sip_invite_domain]=[bling.babblevoice.com] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [sip_auth_realm]=[bling.babblevoice.com] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [hold_music]=[/tmp/prompt_9263bd36-7a8e-11e6-b03a-22000a2293e8.wav] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [sip_authorized]=[true] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [babble_local_call_initiated_by]=[1001@bling.babblevoice.com] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [babble_callrecording_filename]=[/tmp/c5ac2593-ab39-4d81-9844-d87533ef8a18.wav] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [babble_callrecording_uuid]=[c5ac2593-ab39-4d81-9844-d87533ef8a18] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_channel.c:1264 sofia/internal/1001@bling.babblevoice.com EXPORTING[export_vars] [babble_callrecording_accountcode]=[417] to event 2020-10-08 11:41:01.080118 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables 2020-10-08 11:41:01.080118 [DEBUG] switch_ivr_originate.c:2804 Parsing session specific variables 2020-10-08 11:41:01.080118 [NOTICE] switch_channel.c:1118 New Channel sofia/guest/oro6f8gu@9aif0jnhv83f.invalid [34f91e93-b75c-4d35-8cf2-1241b1e43fd4] 2020-10-08 11:41:01.080118 [DEBUG] mod_sofia.c:5089 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State Change CS_NEW -> CS_INIT 2020-10-08 11:41:01.080118 [DEBUG] switch_core_state_machine.c:585 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) Running State Change CS_INIT (Cur 2 Tot 499) 2020-10-08 11:41:01.080118 [DEBUG] switch_core_state_machine.c:628 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State INIT 2020-10-08 11:41:01.080118 [DEBUG] mod_sofia.c:93 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid SOFIA INIT 2020-10-08 11:41:01.080118 [DEBUG] sofia_glue.c:1587 sip:oro6f8gu@82.19.206.102:37416;transport=wss Setting proxy route to sofia/guest/oro6f8gu@9aif0jnhv83f.invalid 2020-10-08 11:41:01.080118 [DEBUG] sofia_glue.c:1618 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid sending invite version: 1.10.5 -release-17-25569c1631 64bit Local SDP: v=0 o=FreeSWITCH 1602135815 1602135816 IN IP4 109.169.12.139 s=FreeSWITCH c=IN IP4 109.169.12.139 t=0 0 a=msid-semantic: WMS M6FyfhYsorle6kXG6PyqkWV4B4H0f3kS m=audio 17846 RTP/SAVPF 9 8 101 13 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fingerprint:sha-256 70:4B:FC:94:C8:41:C4:A3:54:96:8A:DD:6C:FD:CD:20:77:45:82:B7:F2:45:F5:79:81:D9:BB:FB:A7:3A:5A:C4 a=setup:actpass a=rtcp-mux a=rtcp:17846 IN IP4 109.169.12.139 a=ssrc:1403516597 cname:0Qg6X4oclzgiJ4OG a=ssrc:1403516597 msid:M6FyfhYsorle6kXG6PyqkWV4B4H0f3kS a0 a=ssrc:1403516597 mslabel:M6FyfhYsorle6kXG6PyqkWV4B4H0f3kS a=ssrc:1403516597 label:M6FyfhYsorle6kXG6PyqkWV4B4H0f3kSa0 a=ice-ufrag:JdXU0IPrDmiJgtr6 a=ice-pwd:9x2Xrg0DG7Lf1qMBtzlj80BC a=candidate:7905465073 1 udp 659136 109.169.12.139 17846 typ host generation 0 a=candidate:7905465073 2 udp 659136 109.169.12.139 17846 typ host generation 0 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv m=video 16012 RTP/SAVPF 96 b=AS:1024 a=rtpmap:96 VP8/90000 a=sendrecv a=fingerprint:sha-256 70:4B:FC:94:C8:41:C4:A3:54:96:8A:DD:6C:FD:CD:20:77:45:82:B7:F2:45:F5:79:81:D9:BB:FB:A7:3A:5A:C4 a=setup:actpass a=rtcp-mux a=rtcp:16012 IN IP4 109.169.12.139 a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=ssrc:602461518 cname:0Qg6X4oclzgiJ4OG a=ssrc:602461518 msid:M6FyfhYsorle6kXG6PyqkWV4B4H0f3kS v0 a=ssrc:602461518 mslabel:M6FyfhYsorle6kXG6PyqkWV4B4H0f3kS a=ssrc:602461518 label:M6FyfhYsorle6kXG6PyqkWV4B4H0f3kSv0 a=ice-ufrag:lpukiYszsuunde3d a=ice-pwd:7RJ5xqxGy0txrOyC3SMcH5B0 a=candidate:7021569802 1 udp 659136 109.169.12.139 16012 typ host generation 0 a=candidate:7021569802 2 udp 659135 109.169.12.139 16012 typ host generation 0 a=end-of-candidates

2020-10-08 11:41:01.080118 [DEBUG] switch_core_state_machine.c:40 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid Standard INIT 2020-10-08 11:41:01.080118 [DEBUG] switch_core_state_machine.c:48 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State Change CS_INIT -> CS_ROUTING 2020-10-08 11:41:01.080118 [DEBUG] switch_core_state_machine.c:628 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State INIT going to sleep 2020-10-08 11:41:01.100117 [DEBUG] switch_core_state_machine.c:585 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) Running State Change CS_ROUTING (Cur 2 Tot 499) 2020-10-08 11:41:01.100117 [DEBUG] sofia.c:7326 Channel sofia/guest/oro6f8gu@9aif0jnhv83f.invalid entering state [calling][0] 2020-10-08 11:41:01.100117 [DEBUG] switch_core_state_machine.c:644 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State ROUTING 2020-10-08 11:41:01.100117 [DEBUG] mod_sofia.c:154 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid SOFIA ROUTING 2020-10-08 11:41:01.100117 [DEBUG] switch_ivr_originate.c:67 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2020-10-08 11:41:01.100117 [DEBUG] switch_core_state_machine.c:644 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State ROUTING going to sleep 2020-10-08 11:41:01.100117 [DEBUG] switch_core_state_machine.c:585 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 499) 2020-10-08 11:41:01.100117 [DEBUG] switch_core_state_machine.c:663 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State CONSUME_MEDIA 2020-10-08 11:41:01.100117 [DEBUG] switch_core_state_machine.c:663 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State CONSUME_MEDIA going to sleep 2020-10-08 11:41:01.140116 [DEBUG] sofia.c:7326 Channel sofia/guest/oro6f8gu@9aif0jnhv83f.invalid entering state [proceeding][180] 2020-10-08 11:41:01.140116 [NOTICE] sofia.c:7437 Ring-Ready sofia/guest/oro6f8gu@9aif0jnhv83f.invalid! 2020-10-08 11:41:01.140116 [DEBUG] switch_channel.c:3437 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) Callstate Change DOWN -> RINGING 2020-10-08 11:41:01.160120 [INFO] switch_ivr_originate.c:1275 Sending early media 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[iLBC:97:8000:30:13330:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[iLBC:97:8000:30:13330:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[iLBC:97:8000:30:13330:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[iLBC:97:8000:30:13330:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[iLBC:97:8000:30:13330:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[iLBC:97:8000:30:13330:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[iLBC:97:8000:30:13330:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[iLBC:97:8000:30:13330:1] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 110@48000 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/1001@bling.babblevoice.com G722/8000 20 ms 160 samples 64000 bits 1 channels 2020-10-08 11:41:01.160120 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@bling.babblevoice.com Original read codec set to G722:9 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.0.141:43155 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: srflx addr: 82.19.206.102:43155 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate. 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4338 Choose rtp candidate, index 1, 82.19.206.102:43155 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4104 sofia/internal/1001@bling.babblevoice.com choosing family v4 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4349 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 82.19.206.102:43155 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4401 setting remote audio ice addr to index 1 82.19.206.102:43155 based on candidate 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4436 Setting remote rtcp audio addr to 82.19.206.102:43155 based on candidate 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 126@8000 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:5911 sofia/internal/1001@bling.babblevoice.com Set 2833 dtmf send payload to 126 recv payload to 126 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [VP8:96]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6228 Video Codec Compare [VP8:96] +++ is saved as a match 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [rtx:97]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [VP9:98]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [rtx:99]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [VP9:100]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [rtx:101]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [H264:102]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [rtx:121]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [H264:127]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [rtx:120]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [H264:125]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [rtx:107]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [H264:108]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [rtx:109]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [red:124]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [rtx:119]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:6196 Video Codec Compare [ulpfec:123]/[VP8:99] 2020-10-08 11:41:01.160120 [DEBUG] switch_vpx.c:703 VPX VER:v1.8.1 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:8 2020-10-08 11:41:01.160120 [DEBUG] switch_vpx.c:703 VPX VER:v1.8.1 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:8 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:3649 Set VIDEO Codec sofia/internal/1001@bling.babblevoice.com VP8/90000 0 ms 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4284 Save video Candidate cid: 1 proto: udp type: host addr: 192.168.0.141:39515 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4284 Save video Candidate cid: 1 proto: udp type: srflx addr: 82.19.206.102:39515 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate. 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4338 Choose rtp candidate, index 1, 82.19.206.102:39515 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4104 sofia/internal/1001@bling.babblevoice.com choosing family v4 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4349 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 82.19.206.102:39515 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4401 setting remote video ice addr to index 1 82.19.206.102:39515 based on candidate 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:4436 Setting remote rtcp video addr to 82.19.206.102:39515 based on candidate 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/internal/1001@bling.babblevoice.com] 109.169.12.139 port 16072 -> 82.19.206.102 port 43155 codec: 9 ms: 20 2020-10-08 11:41:01.160120 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 160 bytes per 20ms 2020-10-08 11:41:01.160120 [INFO] switch_core_media.c:8845 Activating Audio ICE 2020-10-08 11:41:01.160120 [NOTICE] switch_rtp.c:4952 Activating RTP audio ICE: 1xJ3:NvU7vti89y7OAR5V 82.19.206.102:43155 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:8885 Activating RTCP PORT 43155 2020-10-08 11:41:01.160120 [DEBUG] switch_rtp.c:4848 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 43155 2020-10-08 11:41:01.160120 [INFO] switch_core_media.c:8896 Skipping RTCP ICE (Same as RTP) 2020-10-08 11:41:01.160120 [INFO] switch_rtp.c:3764 Activate RTP/RTCP audio DTLS client 2020-10-08 11:41:01.160120 [INFO] switch_rtp.c:3927 Changing audio DTLS state from OFF to HANDSHAKE 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:8977 sofia/internal/1001@bling.babblevoice.com Set 2833 dtmf send payload to 126 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:8984 sofia/internal/1001@bling.babblevoice.com Set 2833 dtmf receive payload to 126 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:9007 sofia/internal/1001@bling.babblevoice.com Set rtp dtmf delay to 40 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:9013 Set comfort noise payload to 13 2020-10-08 11:41:01.160120 [DEBUG] switch_rtp.c:4465 Starting video timer. 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:9495 VIDEO RTP [sofia/internal/1001@bling.babblevoice.com] 109.169.12.139:14820->82.19.206.102:39515 codec: 96 ms: 0 [SUCCESS] 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:7630 sofia/internal/1001@bling.babblevoice.com Starting Video thread 2020-10-08 11:41:01.160120 [DEBUG] switch_core_media.c:7496 sofia/internal/1001@bling.babblevoice.com Video thread started. Echo is off 2020-10-08 11:41:01.160120 [INFO] switch_core_media.c:9539 Activating Video ICE 2020-10-08 11:41:01.160120 [NOTICE] switch_rtp.c:4952 Activating RTP video ICE: 1xJ3:GxFw2Om1Mtbk5j98 82.19.206.102:39515 2020-10-08 11:41:01.160120 [INFO] switch_core_media.c:9576 Activating VIDEO RTCP PORT 39515 interval 1000 mux 1 2020-10-08 11:41:01.160120 [DEBUG] switch_rtp.c:4848 RTCP send rate is: 1000 and packet rate is: 90000 Remote Port: 39515 2020-10-08 11:41:01.160120 [INFO] switch_core_media.c:9589 Skipping VIDEO RTCP ICE (Same as VIDEO RTP) 2020-10-08 11:41:01.180118 [INFO] switch_rtp.c:3764 Activate RTP/RTCP video DTLS client 2020-10-08 11:41:01.180118 [INFO] switch_rtp.c:3927 Changing video DTLS state from OFF to HANDSHAKE 2020-10-08 11:41:01.180118 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1001@bling.babblevoice.com! 2020-10-08 11:41:01.180118 [DEBUG] switch_channel.c:3565 (sofia/internal/1001@bling.babblevoice.com) Callstate Change RINGING -> EARLY 2020-10-08 11:41:01.180118 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/internal/1001@bling.babblevoice.com. 2020-10-08 11:41:01.180118 [DEBUG] switch_core_media.c:9359 Video params are unchanged for sofia/internal/1001@bling.babblevoice.com. 2020-10-08 11:41:01.180118 [DEBUG] mod_sofia.c:2593 Ring SDP: v=0 o=FreeSWITCH 1602137589 1602137590 IN IP4 109.169.12.139 s=FreeSWITCH c=IN IP4 109.169.12.139 t=0 0 a=msid-semantic: WMS Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq m=audio 16072 UDP/TLS/RTP/SAVPF 9 126 13 a=rtpmap:9 G722/8000 a=rtpmap:126 telephone-event/8000 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv a=fingerprint:sha-256 70:4B:FC:94:C8:41:C4:A3:54:96:8A:DD:6C:FD:CD:20:77:45:82:B7:F2:45:F5:79:81:D9:BB:FB:A7:3A:5A:C4 a=setup:active a=rtcp-mux a=rtcp:16072 IN IP4 109.169.12.139 a=ice-ufrag:NvU7vti89y7OAR5V a=ice-pwd:xFn3NDWMcGqlhWQUiASDU1BU a=candidate:4900315556 1 udp 659136 109.169.12.139 16072 typ host generation 0 a=end-of-candidates a=ssrc:1401636212 cname:uQJCFip28IUOjLGF a=ssrc:1401636212 msid:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq a0 a=ssrc:1401636212 mslabel:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq a=ssrc:1401636212 label:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTqa0 m=video 14820 UDP/TLS/RTP/SAVPF 96 b=AS:1024 a=rtpmap:96 VP8/90000 a=sendrecv a=fingerprint:sha-256 70:4B:FC:94:C8:41:C4:A3:54:96:8A:DD:6C:FD:CD:20:77:45:82:B7:F2:45:F5:79:81:D9:BB:FB:A7:3A:5A:C4 a=setup:active a=rtcp-mux a=rtcp:14820 IN IP4 109.169.12.139 a=rtcp-fb:96 ccm fir a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=ssrc:600581134 cname:uQJCFip28IUOjLGF a=ssrc:600581134 msid:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq v0 a=ssrc:600581134 mslabel:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq a=ssrc:600581134 label:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTqv0 a=ice-ufrag:GxFw2Om1Mtbk5j98 a=ice-pwd:V9yy6nNziFowf8dLwI8onlgZ a=candidate:5105246701 1 udp 659136 109.169.12.139 14820 typ host generation 0 a=end-of-candidates

2020-10-08 11:41:01.180118 [DEBUG] switch_ivr_originate.c:1333 Raw Codec Activation Success L16@16000hz 1 channel 20ms 2020-10-08 11:41:01.180118 [DEBUG] switch_core_codec.c:223 sofia/internal/1001@bling.babblevoice.com Push codec L16:100 2020-10-08 11:41:01.180118 [DEBUG] switch_ivr_originate.c:1407 Play Ringback Tone [%(400,200,400,450);%(400,2200,400,450)] 2020-10-08 11:41:01.200117 [DEBUG] sofia.c:7326 Channel sofia/internal/1001@bling.babblevoice.com entering state [early][183] 2020-10-08 11:41:01.220118 [INFO] switch_vpx.c:564 config: vp8 2020-10-08 11:41:01.220118 [NOTICE] switch_vpx.c:599 VPX encoder reset (WxH/BW) from 0x0/0 to 352x288/1024 2020-10-08 11:41:01.300114 [INFO] switch_rtp.c:3282 Changing audio DTLS state from HANDSHAKE to SETUP 2020-10-08 11:41:01.300114 [INFO] switch_rtp.c:3189 audio Fingerprint Verified. 2020-10-08 11:41:01.300114 [INFO] switch_rtp.c:4254 Activating audio Secure RTP SEND 2020-10-08 11:41:01.300114 [INFO] switch_rtp.c:4232 Activating audio Secure RTP RECV 2020-10-08 11:41:01.300114 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2020-10-08 11:41:01.300114 [INFO] switch_rtp.c:3231 Changing audio DTLS state from SETUP to READY 2020-10-08 11:41:01.300114 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2020-10-08 11:41:01.360116 [INFO] switch_rtp.c:3282 Changing video DTLS state from HANDSHAKE to SETUP 2020-10-08 11:41:01.380120 [DEBUG] switch_rtp.c:1921 rtcp_stats_init: audio ssrc[2927645597] base_seq[7673] 2020-10-08 11:41:01.440114 [INFO] switch_rtp.c:3189 video Fingerprint Verified. 2020-10-08 11:41:01.440114 [INFO] switch_rtp.c:4254 Activating video Secure RTP SEND 2020-10-08 11:41:01.440114 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2020-10-08 11:41:01.440114 [INFO] switch_rtp.c:4232 Activating video Secure RTP RECV 2020-10-08 11:41:01.440114 [INFO] switch_rtp.c:3231 Changing video DTLS state from SETUP to READY 2020-10-08 11:41:01.440114 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2020-10-08 11:41:01.440114 [DEBUG] switch_rtp.c:1921 rtcp_stats_init: video ssrc[2140772957] base_seq[11903] 2020-10-08 11:41:02.260121 [DEBUG] sofia.c:7326 Channel sofia/guest/oro6f8gu@9aif0jnhv83f.invalid entering state [completing][200] 2020-10-08 11:41:02.260121 [DEBUG] sofia.c:7333 Duplicate SDP v=0 o=- 5975346172782042303 2 IN IP4 127.0.0.1 s=- t=0 0 a=msid-semantic: WMS Q1mFI2GLHoMfLU9v2yqhUKzYWcBi8cZomL4I m=audio 42449 RTP/SAVPF 9 8 101 13 c=IN IP4 192.168.0.174 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=rtpmap:13 CN/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1112343425 1 udp 2122260223 192.168.0.174 42449 typ host generation 0 network-id 3 network-cost 10 a=candidate:2051282723 1 udp 2122129151 100.70.216.248 38915 typ host generation 0 network-id 1 network-cost 900 a=ice-ufrag:74Xu a=ice-pwd:0+8OHU9BgTnaJme5c3hV4nD/ a=ice-options:trickle a=fingerprint:sha-256 CC:75:22:C5:08:6C:89:80:BC:EC:34:B4:D4:0A:38:B8:19:50:08:7C:3D:3D:18:D7:4A:B0:AF:40:65:F3:AB:57 a=setup:active a=mid:0 a=rtcp-mux a=ssrc:3766855590 cname:jsfotYLdCkIcC2BS a=ssrc:3766855590 msid:Q1mFI2GLHoMfLU9v2yqhUKzYWcBi8cZomL4I 43804e38-803b-46d1-8c59-4b4a6af2b269 a=ssrc:3766855590 mslabel:Q1mFI2GLHoMfLU9v2yqhUKzYWcBi8cZomL4I a=ssrc:3766855590 label:43804e38-803b-46d1-8c59-4b4a6af2b269 m=video 47661 RTP/SAVPF 96 c=IN IP4 192.168.0.174 a=rtpmap:96 VP8/90000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1112343425 1 udp 2122260223 192.168.0.174 47661 typ host generation 0 network-id 3 network-cost 10 a=candidate:2051282723 1 udp 2122129151 100.70.216.248 44131 typ host generation 0 network-id 1 network-cost 900 a=ice-ufrag:lAzu a=ice-pwd:A011RWQg9yMx0JWlqdx/Gdvs a=ice-options:trickle a=fingerprint:sha-256 CC:75:22:C5:08:6C:89:80:BC:EC:34:B4:D4:0A:38:B8:19:50:08:7C:3D:3D:18:D7:4A:B0:AF:40:65:F3:AB:57 a=setup:active a=mid:1 a=rtcp-mux a=rtcp-fb:96 ccm fir a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=ssrc:67341680 cname:jsfotYLdCkIcC2BS a=ssrc:67341680 msid:Q1mFI2GLHoMfLU9v2yqhUKzYWcBi8cZomL4I 472d354e-6c91-422c-9ee1-e4c7006a3d12 a=ssrc:67341680 mslabel:Q1mFI2GLHoMfLU9v2yqhUKzYWcBi8cZomL4I a=ssrc:67341680 label:472d354e-6c91-422c-9ee1-e4c7006a3d12

2020-10-08 11:41:02.260121 [DEBUG] sofia.c:7326 Channel sofia/guest/oro6f8gu@9aif0jnhv83f.invalid entering state [ready][200] 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 101@8000 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:3839 Set Codec sofia/guest/oro6f8gu@9aif0jnhv83f.invalid G722/8000 20 ms 160 samples 64000 bits 1 channels 2020-10-08 11:41:02.260121 [DEBUG] switch_core_codec.c:111 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid Original read codec set to G722:9 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.0.174:42449 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: host addr: 100.70.216.248:38915 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate. 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4338 Choose rtp candidate, index 1, 100.70.216.248:38915 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4104 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid choosing family v4 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4349 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 100.70.216.248:38915 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4401 setting remote audio ice addr to index 1 100.70.216.248:38915 based on candidate 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4436 Setting remote rtcp audio addr to 100.70.216.248:38915 based on candidate 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 101@8000 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:5911 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid Set 2833 dtmf send payload to 101 recv payload to 101 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:6196 Video Codec Compare [VP8:96]/[VP8:99] 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:6228 Video Codec Compare [VP8:96] +++ is saved as a match 2020-10-08 11:41:02.260121 [DEBUG] switch_vpx.c:703 VPX VER:v1.8.1 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:8 2020-10-08 11:41:02.260121 [DEBUG] switch_vpx.c:703 VPX VER:v1.8.1 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:8 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:3649 Set VIDEO Codec sofia/guest/oro6f8gu@9aif0jnhv83f.invalid VP8/90000 0 ms 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4284 Save video Candidate cid: 1 proto: udp type: host addr: 192.168.0.174:47661 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4284 Save video Candidate cid: 1 proto: udp type: host addr: 100.70.216.248:44131 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate. 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4338 Choose rtp candidate, index 1, 100.70.216.248:44131 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4104 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid choosing family v4 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4349 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 100.70.216.248:44131 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4401 setting remote video ice addr to index 1 100.70.216.248:44131 based on candidate 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:4436 Setting remote rtcp video addr to 100.70.216.248:44131 based on candidate 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/guest/oro6f8gu@9aif0jnhv83f.invalid] 109.169.12.139 port 17846 -> 100.70.216.248 port 38915 codec: 9 ms: 20 2020-10-08 11:41:02.260121 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 160 bytes per 20ms 2020-10-08 11:41:02.260121 [WARNING] switch_rtp.c:4493 You can not have ZRTP and SRTP enabled simultaneously, ZRTP will be disabled for this call! 2020-10-08 11:41:02.260121 [INFO] switch_core_media.c:8845 Activating Audio ICE 2020-10-08 11:41:02.260121 [NOTICE] switch_rtp.c:4952 Activating RTP audio ICE: 74Xu:JdXU0IPrDmiJgtr6 100.70.216.248:38915 2020-10-08 11:41:02.260121 [DEBUG] switch_core_media.c:8885 Activating RTCP PORT 38915 2020-10-08 11:41:02.260121 [DEBUG] switch_rtp.c:4848 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 38915 2020-10-08 11:41:02.280150 [INFO] switch_core_media.c:8896 Skipping RTCP ICE (Same as RTP) 2020-10-08 11:41:02.280150 [INFO] switch_rtp.c:3764 Activate RTP/RTCP audio DTLS server 2020-10-08 11:41:02.280150 [INFO] switch_rtp.c:3927 Changing audio DTLS state from OFF to HANDSHAKE 2020-10-08 11:41:02.280150 [DEBUG] switch_core_media.c:8977 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid Set 2833 dtmf send payload to 101 2020-10-08 11:41:02.280150 [DEBUG] switch_core_media.c:8984 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid Set 2833 dtmf receive payload to 101 2020-10-08 11:41:02.280150 [DEBUG] switch_core_media.c:9007 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid Set rtp dtmf delay to 40 2020-10-08 11:41:02.280150 [DEBUG] switch_core_media.c:9013 Set comfort noise payload to 13 2020-10-08 11:41:02.280150 [DEBUG] switch_rtp.c:4465 Starting video timer. 2020-10-08 11:41:02.280150 [WARNING] switch_rtp.c:4493 You can not have ZRTP and SRTP enabled simultaneously, ZRTP will be disabled for this call! 2020-10-08 11:41:02.280150 [DEBUG] switch_core_media.c:9495 VIDEO RTP [sofia/guest/oro6f8gu@9aif0jnhv83f.invalid] 109.169.12.139:16012->100.70.216.248:44131 codec: 96 ms: 0 [SUCCESS] 2020-10-08 11:41:02.280150 [DEBUG] switch_core_media.c:7630 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid Starting Video thread 2020-10-08 11:41:02.280150 [DEBUG] switch_core_media.c:7496 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid Video thread started. Echo is off 2020-10-08 11:41:02.280150 [INFO] switch_core_media.c:9539 Activating Video ICE 2020-10-08 11:41:02.280150 [NOTICE] switch_rtp.c:4952 Activating RTP video ICE: lAzu:lpukiYszsuunde3d 100.70.216.248:44131 2020-10-08 11:41:02.280150 [INFO] switch_core_media.c:9576 Activating VIDEO RTCP PORT 44131 interval 1000 mux 1 2020-10-08 11:41:02.280150 [DEBUG] switch_rtp.c:4848 RTCP send rate is: 1000 and packet rate is: 90000 Remote Port: 44131 2020-10-08 11:41:02.280150 [INFO] switch_core_media.c:9589 Skipping VIDEO RTCP ICE (Same as VIDEO RTP) 2020-10-08 11:41:02.280150 [INFO] switch_rtp.c:3764 Activate RTP/RTCP video DTLS server 2020-10-08 11:41:02.280150 [INFO] switch_rtp.c:3927 Changing video DTLS state from OFF to HANDSHAKE 2020-10-08 11:41:02.280150 [NOTICE] sofia.c:8504 Channel [sofia/guest/oro6f8gu@9aif0jnhv83f.invalid] has been answered EXECUTE [depth=1] sofia/guest/oro6f8gu@9aif0jnhv83f.invalid lua(onanswer.lua c5ac2593-ab39-4d81-9844-d87533ef8a18) 2020-10-08 11:41:02.300121 [DEBUG] switch_core_codec.c:248 sofia/internal/1001@bling.babblevoice.com Restore previous codec G722:9. 2020-10-08 11:41:02.300121 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/internal/1001@bling.babblevoice.com. 2020-10-08 11:41:02.300121 [DEBUG] switch_core_media.c:9359 Video params are unchanged for sofia/internal/1001@bling.babblevoice.com. 2020-10-08 11:41:02.300121 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/1001@bling.babblevoice.com: v=0 o=FreeSWITCH 1602137589 1602137591 IN IP4 109.169.12.139 s=FreeSWITCH c=IN IP4 109.169.12.139 t=0 0 a=msid-semantic: WMS Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq m=audio 16072 UDP/TLS/RTP/SAVPF 9 126 13 a=rtpmap:9 G722/8000 a=rtpmap:126 telephone-event/8000 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv a=fingerprint:sha-256 70:4B:FC:94:C8:41:C4:A3:54:96:8A:DD:6C:FD:CD:20:77:45:82:B7:F2:45:F5:79:81:D9:BB:FB:A7:3A:5A:C4 a=setup:active a=rtcp-mux a=rtcp:16072 IN IP4 109.169.12.139 a=ice-ufrag:NvU7vti89y7OAR5V a=ice-pwd:xFn3NDWMcGqlhWQUiASDU1BU a=candidate:6116007728 1 udp 659136 109.169.12.139 16072 typ host generation 0 a=end-of-candidates a=ssrc:1401636212 cname:uQJCFip28IUOjLGF a=ssrc:1401636212 msid:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq a0 a=ssrc:1401636212 mslabel:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq a=ssrc:1401636212 label:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTqa0 m=video 14820 UDP/TLS/RTP/SAVPF 96 b=AS:1024 a=rtpmap:96 VP8/90000 a=sendrecv a=fingerprint:sha-256 70:4B:FC:94:C8:41:C4:A3:54:96:8A:DD:6C:FD:CD:20:77:45:82:B7:F2:45:F5:79:81:D9:BB:FB:A7:3A:5A:C4 a=setup:active a=rtcp-mux a=rtcp:14820 IN IP4 109.169.12.139 a=rtcp-fb:96 ccm fir a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=ssrc:600581134 cname:uQJCFip28IUOjLGF a=ssrc:600581134 msid:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq v0 a=ssrc:600581134 mslabel:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTq a=ssrc:600581134 label:Ls6shZIXw0t1PK12wbZouaJlMQp9PcTqv0 a=ice-ufrag:GxFw2Om1Mtbk5j98 a=ice-pwd:V9yy6nNziFowf8dLwI8onlgZ a=candidate:0791492264 1 udp 659136 109.169.12.139 14820 typ host generation 0 a=end-of-candidates

2020-10-08 11:41:02.300121 [DEBUG] sofia.c:7326 Channel sofia/internal/1001@bling.babblevoice.com entering state [completed][200] 2020-10-08 11:41:02.320304 [NOTICE] switch_ivr_originate.c:3794 Channel [sofia/internal/1001@bling.babblevoice.com] has been answered 2020-10-08 11:41:02.320304 [NOTICE] switch_cpp.cpp:1447 Call answered - running onanswer.lua 2020-10-08 11:41:02.320304 [DEBUG] switch_cpp.cpp:1191 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid destroy/unlink session from object 2020-10-08 11:41:02.320304 [INFO] switch_core_session.c:1680 sofia/internal/1001@bling.babblevoice.com setting session heartbeat to 20 second(s). 2020-10-08 11:41:02.320304 [DEBUG] switch_channel.c:3865 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) Callstate Change RINGING -> ACTIVE EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com lua(onanswer.lua c5ac2593-ab39-4d81-9844-d87533ef8a18) 2020-10-08 11:41:02.360144 [NOTICE] switch_cpp.cpp:1447 Call answered - running onanswer.lua 2020-10-08 11:41:02.360144 [NOTICE] switch_cpp.cpp:1447 Starting recording of session EXECUTE [depth=0] sofia/internal/1001@bling.babblevoice.com record_session(/tmp/c5ac2593-ab39-4d81-9844-d87533ef8a18.wav) 2020-10-08 11:41:02.360144 [INFO] switch_core_session.c:1680 sofia/internal/1001@bling.babblevoice.com setting session heartbeat to 20 second(s). 2020-10-08 11:41:02.380140 [DEBUG] switch_ivr_async.c:1351 Record session sample rate: 16000 -> 16000 2020-10-08 11:41:02.380140 [DEBUG] switch_core_media_bug.c:970 Attaching BUG to sofia/internal/1001@bling.babblevoice.com 2020-10-08 11:41:02.380140 [DEBUG] switch_cpp.cpp:1191 sofia/internal/1001@bling.babblevoice.com destroy/unlink session from object 2020-10-08 11:41:02.380140 [DEBUG] switch_channel.c:3865 (sofia/internal/1001@bling.babblevoice.com) Callstate Change EARLY -> ACTIVE 2020-10-08 11:41:02.380140 [DEBUG] sofia.c:7326 Channel sofia/internal/1001@bling.babblevoice.com entering state [ready][200] 2020-10-08 11:41:02.380140 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/guest/oro6f8gu@9aif0jnhv83f.invalid] 2020-10-08 11:41:02.380140 [INFO] switch_vpx.c:564 config: vp8 2020-10-08 11:41:02.380140 [NOTICE] switch_vpx.c:599 VPX encoder reset (WxH/BW) from 0x0/0 to 352x288/1024 2020-10-08 11:41:02.400380 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/guest/oro6f8gu@9aif0jnhv83f.invalid] 2020-10-08 11:41:02.400380 [DEBUG] switch_ivr_bridge.c:1793 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2020-10-08 11:41:02.400380 [DEBUG] switch_core_state_machine.c:585 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 499) 2020-10-08 11:41:02.400380 [DEBUG] switch_core_state_machine.c:654 (sofia/guest/oro6f8gu@9aif0jnhv83f.invalid) State EXCHANGE_MEDIA 2020-10-08 11:41:02.400380 [DEBUG] mod_sofia.c:656 SOFIA EXCHANGE_MEDIA 2020-10-08 11:41:02.400380 [DEBUG] switch_ivr_bridge.c:495 Setup generated silence from sofia/internal/1001@bling.babblevoice.com to sofia/guest/oro6f8gu@9aif0jnhv83f.invalid at 1400 2020-10-08 11:41:02.420589 [DEBUG] switch_ivr_async.c:1640 No silence detection configured; assuming start of speech 2020-10-08 11:41:02.442266 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('bridge_generate_comfort_noise', 'true') 2020-10-08 11:41:02.442266 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('hold_music', '/tmp/prompt_9263bd36-7a8e-11e6-b03a-22000a2293e8.wav') 2020-10-08 11:41:02.442266 [NOTICE] switch_cpp.cpp:1447 onbridge.lua completed 2020-10-08 11:41:02.442266 [DEBUG] switch_cpp.cpp:1191 sofia/guest/oro6f8gu@9aif0jnhv83f.invalid destroy/unlink session from object 2020-10-08 11:41:02.442266 [DEBUG] switch_cpp.cpp:1191 sofia/internal/1001@bling.babblevoice.com destroy/unlink session from object 2020-10-08 11:41:02.820117 [DEBUG] switch_core_io.c:448 Setting BUG Codec G722:9 2020-10-08 11:41:04.540115 [NOTICE] switch_rtp.c:1301 Auto Changing video stun/rtp/dtls port from 100.70.216.248:44131 to 82.19.206.102:47661 idx:-1 2020-10-08 11:41:04.560122 [NOTICE] switch_rtp.c:1301 Auto Changing audio stun/rtp/dtls port from 100.70.216.248:38915 to 82.19.206.102:42449 idx:-1 2020-10-08 11:41:05.880115 [INFO] switch_rtp.c:3282 Changing audio DTLS state from HANDSHAKE to SETUP 2020-10-08 11:41:05.900117 [INFO] switch_rtp.c:3189 audio Fingerprint Verified. 2020-10-08 11:41:05.900117 [INFO] switch_rtp.c:4254 Activating audio Secure RTP SEND 2020-10-08 11:41:05.900117 [INFO] switch_rtp.c:4232 Activating audio Secure RTP RECV 2020-10-08 11:41:05.900117 [INFO] switch_rtp.c:3231 Changing audio DTLS state from SETUP to READY 2020-10-08 11:41:05.900117 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2020-10-08 11:41:05.900117 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2020-10-08 11:41:06.060113 [DEBUG] switch_rtp.c:1921 rtcp_stats_init: audio ssrc[3766855590] base_seq[7987] 2020-10-08 11:41:06.620116 [INFO] switch_rtp.c:3282 Changing video DTLS state from HANDSHAKE to SETUP 2020-10-08 11:41:06.720116 [INFO] switch_rtp.c:3189 video Fingerprint Verified. 2020-10-08 11:41:06.720116 [INFO] switch_rtp.c:4254 Activating video Secure RTP SEND 2020-10-08 11:41:06.720116 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2020-10-08 11:41:06.720116 [INFO] switch_rtp.c:4232 Activating video Secure RTP RECV 2020-10-08 11:41:06.720116 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2020-10-08 11:41:06.720116 [INFO] switch_rtp.c:3231 Changing video DTLS state from SETUP to READY 2020-10-08 11:41:06.760116 [DEBUG] switch_rtp.c:1921 rtcp_stats_init: video ssrc[67341680] base_seq[3991]

tinpotnick commented 4 years ago

I have set rtp-rewrite-timestamps to true on all profiles and this has improved it. So I'll close this now and continue to test.

DustinQi commented 2 years ago

thanks @tinpotnick, your answer gives me a lot of inspiration!

PMCME commented 8 months ago

@tinpotnick Please provide some details with code.

tinpotnick commented 8 months ago

Hi,

I have been moving away from FS so getting more debug will be tricky.

There is a fundamental problem with how you read RTP data from the underlying socket. You read it every 20mS which if a stream stalls and restarts with a burst, this builds up in the underlying socket buffer and remains for the duration of the call. The buffer is exactly 4 seconds for g711.

The temporary fix is to use iptables to drop any packets over the rate the connection expects.

The proper fix should be done which reads the RTP socket.