[Freeswitch-users] FreeSWITCH 1.6 WebRTC slow connection time

[Adam Ben-Ayoun]

The ticket is at https://freeswitch.org/jira/browse/FS-7703 for reference.

On 22 June 2015 at 10:04, Adam Ben-Ayoun <adam.ben.ayoun1 at gmail.com> wrote:

> Yes. I will open a ticket.
>
> On 20 June 2015 at 22:58, Michael Jerris <mike at jerris.com> wrote:
>
>> 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
>>>
>>
>> _________________________________________________________________________
>> Professional FreeSWITCH Consulting Services:
>> consulting at freeswitch.org
>> http://www.freeswitchsolutions.com
>>
>> Official FreeSWITCH Sites
>> http://www.freeswitch.org
>> http://confluence.freeswitch.org
>> http://www.cluecon.com
>>
>> FreeSWITCH-users mailing list
>> FreeSWITCH-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150622/ee2e4839/attachment-0001.html