[QUESTION] KVS Client Sample Viewer sending the first signaling message takes 10 seconds on Windows

[mehmetcy84]

Environment:
Latest unmodified Kinesis repo 1.9 built on Windows 10 64 bit. Built with build_windows_openssl.bat.

Issue:
The first signalling message sent from the client takes up to 10 seconds irrespective of its content/size. Using the unmodified kvsWebRTCClientViewer.exe against the WebRTC Test Page running as master.

The first signalling message ever sent from the client to the master takes 10 seconds. This is the case if I enabled or disabled useTURN, or TrickleICE. For all 4 combinations for these 2 parameters, independent from whatever signaling message goes first, the first and only the first signalling message being sent always takes 10 seconds, and the following signalling messages, if there are any, takes negligible time in comparison.

After testing the default, I modified the TURN, and TrickleICE boolean flags passed to the createSampleConfiguration function in samples/Common.c for test:
CHK_STATUS(createSampleConfiguration(pChannelName, SIGNALING_CHANNEL_ROLE_TYPE_VIEWER, TRUE, TRUE, logLevel, &pSampleConfiguration));

Here are all the logs for these cases:

TrickleICE=TRUE, UseTURN=TRUE (unmodified default)
TrickleICE=TRUE, UseTURN=FALSE
TrickleICE=FALSE, UseTURN=TRUE
TrickleICE=FALSE, UseTURN=FALSE
TrickleICE_OFF-TURN_OFF.txt
TrickleICE_OFF-TURN_ON.txt
TrickleICE_ON-TURN_OFF.txt
TrickleICE_ON-TURN_ON.txt

Here is a portion of logs from the default case:
...
2023-11-27 14:21:25.837 PROFILE iceAgentStartGathering(): [Relay candidates setup time] Time taken: 0 ms
2023-11-27 14:21:25.837 INFO main(): [KVS Viewer] Completed setting local description
2023-11-27 14:21:25.838 INFO main(): [KVS Viewer] Offer creation successful
2023-11-27 14:21:25.838 INFO main(): [KVS Viewer] Generating JSON of session description....
2023-11-27 14:21:25.838 VERBOSE signalingClientSendMessageSync(): Signaling Client Sending Message Sync
2023-11-27 14:21:25.839 DEBUG sendLwsMessage(): SDP_OFFER
...
2023-11-27 14:21:35.724 INFO main(): [KVS Viewer] Creating data channel...completed
2023-11-27 14:21:35.724 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2023-11-27 14:21:35.724 DEBUG lwsWssCallbackRoutine(): Client is writable
2023-11-27 14:21:35.724 INFO main(): [KVS Viewer] Data Channel open now...

And this is a portion from the TURN=OFF TrickleICE=OFF case:
...
2023-11-27 15:40:29.387 INFO main(): [KVS Viewer] Candidate collection completed
2023-11-27 15:40:29.388 INFO main(): [KVS Viewer] Offer creation successful
2023-11-27 15:40:29.388 INFO main(): [KVS Viewer] Generating JSON of session description....
2023-11-27 15:40:29.388 VERBOSE signalingClientSendMessageSync(): Signaling Client Sending Message Sync
...
2023-11-27 15:40:39.195 DEBUG lwsWssCallbackRoutine(): Client is writable
2023-11-27 15:40:39.195 INFO main(): [KVS Viewer] Creating data channel...completed
2023-11-27 15:40:39.195 INFO main(): [KVS Viewer] Data Channel open now...
2023-11-27 15:40:39.195 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2023-11-27 15:40:39.196 DEBUG lwsWssCallbackRoutine(): Client is writable

[stefankiesz]

Hi, can you check whether this delay persists when using the latest develop branch.

[mehmetcy84]

Hi
I have checked out the latest develop but the build fails with the following error:

E:\webrtc\src\source\Ice\TurnConnection.c(18): error C2065: 'MAX_STATE_MACHINE_NAME_LENGTH': undeclared identifier
E:\webrtc\src\source\Ice\TurnConnection.c(18): error C2057: expected constant expression
E:\webrtc\src\source\Ice\TurnConnection.c(18): error C2466: cannot allocate an array of constant size 0
E:\webrtc\src\source\Ice\TurnConnection.c(18): error C2133: 'turnStateMachineName': unknown size
E:\webrtc\src\source\Ice\TurnConnection.c(65): error C2065: 'MAX_STATE_MACHINE_NAME_LENGTH': undeclared identifier

If I manually add a definition for MAX_STATE_MACHINE_NAME_LENGTH, and rebuild, the build still fails with the following:

kvsWebrtcClient.lib(IceAgent.c.obj) : error LNK2019: unresolved external symbol createStateMachineWithName referenced in function createIceAgent
kvsWebrtcClient.lib(TurnConnection.c.obj) : error LNK2001: unresolved external symbol createStateMachineWithName
kvsWebrtcSignalingClient.lib(Signaling.c.obj) : error LNK2001: unresolved external symbol createStateMachineWithName
kvsWebrtcClient.lib(IceAgentStateMachine.c.obj) : error LNK2019: unresolved external symbol checkForStateTransition referenced in function checkIceAgentStateMachine
kvsWebrtcClient.lib(TurnConnectionStateMachine.c.obj) : error LNK2001: unresolved external symbol checkForStateTransition
kvsWebrtcClient.lib(IceAgentStateMachine.c.obj) : error LNK2019: unresolved external symbol timerQueueKick referenced in function checkIceAgentStateMachine
kvsWebrtcClient.lib(TurnConnectionStateMachine.c.obj) : error LNK2001: unresolved external symbol timerQueueKick
kvsWebrtcClientMaster.exe : fatal error LNK1120: 3 unresolved externals

I checked older commits, and found that this commit introduced the createStateMachineWithName call:
SHA-1: a03c26c (10/16/2023)

• Ice turn sleepless state machine (Ice turn sleepless state machine #1825)

So, the latest develop commit that builds for me is:
SHA-1: 3ba7c05 (10/13/2023)
And all the later ones are failing during the build.

I built this version: SHA-1: 3ba7c05 (10/13/2023), and the 10 seconds delay is still there. And I couldn't test any of the later commits.

[disa6302]

@mehmetcy84 ,

You would have to clean build. The createStateMachineWithName is a PIC definition which does not exist in the past release.

[mehmetcy84]

I deleted build and open-source folders. Ran build_windows_openssl.bat again, this time build fails at this step:

[ 36%] Building C object lib/CMakeFiles/websockets.dir/roles/ws/client-parser-ws.c.obj
client-parser-ws.c
E:\webrtc\open-source\libwebsockets\build\src\project_libwebsockets\lib\roles\ws\client-parser-ws.c(480): error C2220: warning treated as error - no 'object' file generated
E:\webrtc\open-source\libwebsockets\build\src\project_libwebsockets\lib\roles\ws\client-parser-ws.c(480): warning C4003: not enough arguments for function-like macro invocation 'lwsl_hexdump_wsi'
E:\webrtc\open-source\libwebsockets\build\src\project_libwebsockets\lib\roles\ws\client-parser-ws.c(480): error C2059: syntax error: ')'
E:\webrtc\open-source\libwebsockets\build\src\project_libwebsockets\lib\roles\ws\client-parser-ws.c(598): warning C4003: not enough arguments for function-like macro invocation 'lwsl_hexdump_wsi'
E:\webrtc\open-source\libwebsockets\build\src\project_libwebsockets\lib\roles\ws\client-parser-ws.c(598): error C2059: syntax error: ')'
NMAKE : fatal error U1077: '"C:\Program Files\CMake\bin\cmake.exe"' : return code '0x2'
Stop.
NMAKE : fatal error U1077: '"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\VC\Tools\MSVC\14.16.27023\bin\HostX64\x64\nmake.exe"' : return code '0x2'
Stop.
NMAKE : fatal error U1077: '"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\VC\Tools\MSVC\14.16.27023\bin\HostX64\x64\nmake.exe"' : return code '0x2'
Stop.
NMAKE : fatal error U1077: '"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\VC\Tools\MSVC\14.16.27023\bin\HostX64\x64\nmake.exe"' : return code '0x2'
Stop.
NMAKE : fatal error U1077: '"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\VC\Tools\MSVC\14.16.27023\bin\HostX64\x64\nmake.exe"' : return code '0x2'
Stop.
NMAKE : fatal error U1077: '"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\VC\Tools\MSVC\14.16.27023\bin\HostX64\x64\nmake.exe"' : return code '0x2'
Stop.
CMake Error at CMake/Utilities.cmake:75 (message):
CMake step for libwebsockets failed: 2
Call Stack (most recent call first):
CMakeLists.txt:186 (build_dependency)

[niyatim23]

Hi @mehmetcy84, I just tried this on a Windows EC2 instance and I do not see it taking 10 seconds:

PS C:\Users\Administrator\Desktop\w\build\samples> .\kvsWebrtcClientViewer.exe ninja
2024-02-06 18:29:11.277 PROFILE createRtcCertificate(): [Certificate creation time] Time taken: 0 ms

2024-02-06 18:29:11.658 VERBOSE signalingClientStateChanged(): Signaling client state changed to 9 - 'Connected'

This seems like it could be specific to your configuration somehow. Please let us know if anything has changed for you since the last comment

[mehmetcy84]

Hi @niyatim23
The call which takes 10 seconds is not about the signaling client connecting.
Once the signaling client is connected, and the first signaling message sending attempt is done, it takes 10 seconds to return from the call for signalingSendMessageSync.

2024-03-06 14:16:01.017 INFO signalingSendMessageSync(): MEHMET Signaling.c>> signalingSendMessageSync-2 calling sendLwsMessage
2024-03-06 14:16:01.017 DEBUG sendLwsMessage(): SDP_OFFER
.
.
.
2024-03-06 14:16:10.909 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2024-03-06 14:16:10.909 DEBUG lwsWssCallbackRoutine(): Client is writable
2024-03-06 14:16:10.911 INFO signalingSendMessageSync(): MEHMET Signaling.c>> signalingSendMessageSync-3 called sendLwsMessage

I put these prints in:
Source/Signaling/Signaling.c
in
STATUS signalingSendMessageSync(PSignalingClient pSignalingClient, PSignalingMessage pSignalingMessage)
just one line above and below the SendLwsMessage call:

// Perform the call
    DLOGI("MEHMET Signaling.c>> signalingSendMessageSync-2 calling sendLwsMessage");
    CHK_STATUS(sendLwsMessage(pSignalingClient, pSignalingMessage->messageType, pSignalingMessage->peerClientId, pSignalingMessage->payload,
                              pSignalingMessage->payloadLen, pSignalingMessage->correlationId, 0));
    DLOGI("MEHMET Signaling.c>> signalingSendMessageSync-3 called sendLwsMessage");

I attached the full logs for both cases where I set TrickleICE=TRUE and TrickleICE=FALSE on the client side.
When the TrickleICE=TRUE is set, during this 10 seconds of wait, the concurrently handled ice candidate sending attempts fail.
Yet the wait is not "caused" by those failures. When I select TrickleICE=TRUE, only a single signaling message is sent from the client, and, it again takes 10 seconds to return from SendLwsMessage, with no other interfering message sending attempts.
signalingTrickleICEON.txt
signallingTrickleIceOFF.txt

[mehmetcy84]

Hi @niyatim23
Tested this with KVS 1.10.1 build with default kvsWebRTCClientViewer and the issue still exists for me.