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@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@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@anonymous.invalid] has been answered 2015-06-20 16:28:37.838233 [DEBUG] switch_channel.c:3759 (sofia/internal/anonymous.jb4692@anonymous.invalid) Callstate Change EARLY -> ACTIVE 2015-06-20 16:28:37.838233 [DEBUG] switch_ivr.c:195 Codec Activated L16@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@anonymous.invalid conference(1234-172.30.0.123@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@16000hz 1 channel 30ms 2015-06-20 16:28:41.878188 [DEBUG] mod_conference.c:11617 Raw Codec Activation Success L16@16000hz 1 channel 30ms 2015-06-20 16:28:41.878188 [DEBUG] switch_core_codec.c:221 sofia/internal/anonymous.jb4692@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@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@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@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@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@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@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@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@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@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@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@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@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