[Freeswitch-users] FreeSWITCH 1.6 WebRTC slow connection time

[Michael Jerris]

can you confirm if the behavior is the same using verto?  please open a bug
at https://FreeSWITCH.org/jira on this issue.

On Saturday, June 20, 2015, Adam Ben-Ayoun <adam.ben.ayoun1 at gmail.com>
wrote:

> Hi guys,
>
> Since we upgraded to 1.6, it takes up to 5 seconds for media to actually
> flow after DTLS state becomes READY, this did not happen on 1.4. We are
> using sipjs and test clients on Android and iOS, the issue reproduces on
> all of them. Connection time used to take about 2.5-3 seconds and now it
> actually takes 7-8 seconds.
>
> Here are the relevant FreeSWITCH logs:
>
>
> 2015-06-20 16:28:36.458187 [DEBUG] sofia.c:6701 Channel
> sofia/internal/anonymous.jb4692 at anonymous.invalid entering state
> [ready][200]
> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
> nta.c:1289 agent_timer() nta: timer not set
> 2015-06-20 16:28:37.838233 [INFO] switch_rtp.c:3006 Changing audio DTLS
> state from HANDSHAKE to SETUP
> 2015-06-20 16:28:37.838233 [INFO] switch_rtp.c:2915 audio Fingerprint
> Verified.
> 2015-06-20 16:28:37.838233 [INFO] switch_rtp.c:3495 Activating Audio
> Secure RTP SEND
> 2015-06-20 16:28:37.838233 [DEBUG] switch_core_sqldb.c:2599 Secure Type:
> srtp:dtls:AES_CM_128_HMAC_SHA1_80
> 2015-06-20 16:28:37.838233 [INFO] switch_rtp.c:3473 Activating Audio
> Secure RTP RECV
> 2015-06-20 16:28:37.838233 [DEBUG] switch_core_sqldb.c:2599 Secure Type:
> srtp:dtls:AES_CM_128_HMAC_SHA1_80
> 2015-06-20 16:28:37.838233 [INFO] switch_rtp.c:2955 Changing audio DTLS
> state from SETUP to READY
> 2015-06-20 16:28:37.838233 [NOTICE] mod_dptools.c:1292 Channel
> [sofia/internal/anonymous.jb4692 at anonymous.invalid] has been answered
> 2015-06-20 16:28:37.838233 [DEBUG] switch_channel.c:3759
> (sofia/internal/anonymous.jb4692 at anonymous.invalid) Callstate Change
> EARLY -> ACTIVE
> 2015-06-20 16:28:37.838233 [DEBUG] switch_ivr.c:195 Codec Activated
> L16 at 16000hz 1 channels 30ms
> 2015-06-20 16:28:37.878249 [DEBUG] switch_rtp.c:1775 rtcp_stats_init:
> audio ssrc[3304298062] base_seq[31262]
> EXECUTE sofia/internal/anonymous.jb4692 at anonymous.invalid
> conference(1234-172.30.0.123 at test)
> 2015-06-20 16:28:41.878188 [INFO] mod_conference.c:13067 using channel
> sound prefix: /usr/local/freeswitch/sounds/en/us/callie
> 2015-06-20 16:28:41.878188 [DEBUG] mod_conference.c:11570 Raw Codec
> Activation Success L16 at 16000hz 1 channel 30ms
> 2015-06-20 16:28:41.878188 [DEBUG] mod_conference.c:11617 Raw Codec
> Activation Success L16 at 16000hz 1 channel 30ms
> 2015-06-20 16:28:41.878188 [DEBUG] switch_core_codec.c:221
> sofia/internal/anonymous.jb4692 at anonymous.invalid Push codec L16:100
> 2015-06-20 16:28:41.878188 [DEBUG] mod_conference.c:4992 Setup timer
> success interval: 30  samples: 480
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '0' to 'mute'
> 2015-06-20 16:28:41.898176 [INFO] switch_ivr_async.c:213 Digit parser
> mod_conference: Setting realm to 'conf'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 0/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290166f18
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '*' to 'deaf
> mute'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding */conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290166f48
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '9' to 'energy
> up'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 9/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290166f78
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '8' to 'energy
> equ'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 8/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290166fa8
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '7' to 'energy
> dn'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 7/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290166fd8
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '3' to 'vol
> talk up'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 3/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290167008
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '2' to 'vol
> talk zero'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 2/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290167038
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '1' to 'vol
> talk dn'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 1/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290167068
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '6' to 'vol
> listen up'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 6/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290167098
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '5' to 'vol
> listen zero'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 5/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f42901670c8
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '4' to 'vol
> listen dn'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding 4/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f42901670f8
> 2015-06-20 16:28:41.898176 [INFO] mod_conference.c:13676
> sofia/internal/anonymous.jb4692 at anonymous.invalid binding '#' to 'hangup'
> 2015-06-20 16:28:41.898176 [DEBUG] switch_ivr_async.c:322 Digit parser
> mod_conference: binding #/conf/0 callback: 0x7f429d09adb0 data:
> 0x7f4290167128
> 2015-06-20 16:28:41.898176 [DEBUG] mod_conference.c:6751 Setup timer soft
> success interval: 30  samples: 480
> 2015-06-20 16:28:41.918188 [DEBUG] mod_conference.c:5127 Auto recording
> file: /tmp/record.wav
> 2015-06-20 16:28:41.938180 [DEBUG] mod_conference.c:7178 Setup timer
> success interval: 30  samples: 480
>
> As you can see at 2015-06-20 16:28:37.838233, the DTLS handshake
> completed, the call was answered and the client is thinking that media is
> connect but in fact only at 2015-06-20 16:28:41.938180 media opens. Any
> idea?
>
> Thanks,
> Adam
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150620/e77fd7dc/attachment-0001.html