[Freeswitch-users] FreeSWITCH 1.6 WebRTC slow connection time

[Adam Ben-Ayoun]

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/875b4d73/attachment.html