From 8c2702bfd823ea3ba89c556032a9f210b4461a2c Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Wed, 3 Jan 2024 12:04:18 -0800 Subject: [PATCH 1/9] Use timeout value instead of counter for allocation --- src/source/Ice/TurnConnection.h | 4 ---- src/source/Ice/TurnConnectionStateMachine.c | 8 +++----- 2 files changed, 3 insertions(+), 9 deletions(-) diff --git a/src/source/Ice/TurnConnection.h b/src/source/Ice/TurnConnection.h index 4e9d8d6bdc..28c765e54c 100644 --- a/src/source/Ice/TurnConnection.h +++ b/src/source/Ice/TurnConnection.h @@ -37,8 +37,6 @@ extern "C" { #define DEFAULT_TURN_CHANNEL_DATA_BUFFER_SIZE 512 #define DEFAULT_TURN_MAX_PEER_COUNT 32 -#define DEFAULT_TURN_ALLOCATION_MAX_TRY_COUNT 3 - // all turn channel numbers must be greater than 0x4000 and less than 0x7FFF #define TURN_CHANNEL_BIND_CHANNEL_NUMBER_BASE (UINT16) 0x4000 @@ -134,8 +132,6 @@ struct __TurnConnection { UINT64 state; UINT64 stateTimeoutTime; - UINT32 stateTryCount; - UINT32 stateTryCountMax; STATUS errorStatus; diff --git a/src/source/Ice/TurnConnectionStateMachine.c b/src/source/Ice/TurnConnectionStateMachine.c index 0a7dfd82d5..00421bd6b0 100644 --- a/src/source/Ice/TurnConnectionStateMachine.c +++ b/src/source/Ice/TurnConnectionStateMachine.c @@ -261,8 +261,6 @@ STATUS fromGetCredentialsTurnState(UINT64 customData, PUINT64 pState) if (pTurnConnection->credentialObtained) { state = TURN_STATE_ALLOCATION; pTurnConnection->stateTimeoutTime = currentTime + DEFAULT_TURN_ALLOCATION_TIMEOUT; - pTurnConnection->stateTryCountMax = DEFAULT_TURN_ALLOCATION_MAX_TRY_COUNT; - pTurnConnection->stateTryCount = 0; } *pState = state; @@ -347,9 +345,10 @@ STATUS executeAllocationTurnState(UINT64 customData, UINT64 time) UNUSED_PARAM(time); STATUS retStatus = STATUS_SUCCESS; PTurnConnection pTurnConnection = (PTurnConnection) customData; - + UINT64 currentTime; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); + currentTime = GETTIME(); if (pTurnConnection->state != TURN_STATE_ALLOCATION) { DLOGV("Updated turn allocation request credential after receiving 401"); @@ -363,8 +362,7 @@ STATUS executeAllocationTurnState(UINT64 customData, UINT64 time) DEFAULT_TURN_ALLOCATION_LIFETIME_SECONDS, &pTurnConnection->pTurnPacket)); pTurnConnection->state = TURN_STATE_ALLOCATION; } else { - pTurnConnection->stateTryCount++; - CHK(pTurnConnection->stateTryCount < pTurnConnection->stateTryCountMax, STATUS_TURN_CONNECTION_ALLOCATION_FAILED); + CHK(currentTime < pTurnConnection->stateTimeoutTime, STATUS_TURN_CONNECTION_ALLOCATION_FAILED); } CHK_STATUS(iceUtilsSendStunPacket(pTurnConnection->pTurnPacket, pTurnConnection->longTermKey, ARRAY_SIZE(pTurnConnection->longTermKey), &pTurnConnection->turnServer.ipAddress, pTurnConnection->pControlChannel, NULL, FALSE)); From 1d23f064b853e38a7f184d707a9d44b6de253d1c Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Wed, 3 Jan 2024 12:22:37 -0800 Subject: [PATCH 2/9] Add timeout for get credentials too and change all timeouts to a standard 5 seconds --- .../kinesis/video/webrtcclient/Include.h | 2 ++ src/source/Ice/TurnConnection.h | 5 ++--- src/source/Ice/TurnConnectionStateMachine.c | 18 ++++++++++++------ 3 files changed, 16 insertions(+), 9 deletions(-) diff --git a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h index a3c990ea7a..b84133b420 100644 --- a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h +++ b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h @@ -255,6 +255,8 @@ extern "C" { #define STATUS_ICE_CANDIDATE_STRING_MISSING_TYPE STATUS_ICE_BASE + 0x00000029 #define STATUS_TURN_CONNECTION_ALLOCATION_FAILED STATUS_ICE_BASE + 0x0000002a #define STATUS_TURN_INVALID_STATE STATUS_ICE_BASE + 0x0000002b +#define STATUS_TURN_CONNECTION_GET_CREDENTIALS_FAILED STATUS_ICE_BASE + 0x0000002c + /*!@} */ ///////////////////////////////////////////////////// diff --git a/src/source/Ice/TurnConnection.h b/src/source/Ice/TurnConnection.h index 28c765e54c..f1293ffbed 100644 --- a/src/source/Ice/TurnConnection.h +++ b/src/source/Ice/TurnConnection.h @@ -21,11 +21,10 @@ extern "C" { #define DEFAULT_TURN_SEND_REFRESH_INVERVAL (1 * HUNDREDS_OF_NANOS_IN_A_SECOND) // turn state timeouts -#define DEFAULT_TURN_SOCKET_CONNECT_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) #define DEFAULT_TURN_GET_CREDENTIAL_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) #define DEFAULT_TURN_ALLOCATION_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define DEFAULT_TURN_CREATE_PERMISSION_TIMEOUT (2 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define DEFAULT_TURN_BIND_CHANNEL_TIMEOUT (3 * HUNDREDS_OF_NANOS_IN_A_SECOND) +#define DEFAULT_TURN_CREATE_PERMISSION_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) +#define DEFAULT_TURN_BIND_CHANNEL_TIMEOUT (5 * HUNDREDS_OF_NANOS_IN_A_SECOND) #define DEFAULT_TURN_CLEAN_UP_TIMEOUT (10 * HUNDREDS_OF_NANOS_IN_A_SECOND) #define DEFAULT_TURN_ALLOCATION_REFRESH_GRACE_PERIOD (30 * HUNDREDS_OF_NANOS_IN_A_SECOND) diff --git a/src/source/Ice/TurnConnectionStateMachine.c b/src/source/Ice/TurnConnectionStateMachine.c index 00421bd6b0..f4333286c9 100644 --- a/src/source/Ice/TurnConnectionStateMachine.c +++ b/src/source/Ice/TurnConnectionStateMachine.c @@ -159,7 +159,6 @@ STATUS fromNewTurnState(UINT64 customData, PUINT64 pState) CHK(pTurnConnection != NULL && pState != NULL, STATUS_NULL_ARG); state = TURN_STATE_CHECK_SOCKET_CONNECTION; - *pState = state; CleanUp: @@ -191,6 +190,7 @@ STATUS fromCheckSocketConnectionTurnState(UINT64 customData, PUINT64 pState) PTurnConnection pTurnConnection = (PTurnConnection) customData; UINT64 state = TURN_STATE_CHECK_SOCKET_CONNECTION; BOOL locked = FALSE; + UINT64 currentTime; CHK(pTurnConnection != NULL && pState != NULL, STATUS_NULL_ARG); @@ -201,8 +201,10 @@ STATUS fromCheckSocketConnectionTurnState(UINT64 customData, PUINT64 pState) CHK(FALSE, STATUS_SUCCESS); } + currentTime = GETTIME(); if (socketConnectionIsConnected(pTurnConnection->pControlChannel)) { state = TURN_STATE_GET_CREDENTIALS; + pTurnConnection->stateTimeoutTime = currentTime + DEFAULT_TURN_GET_CREDENTIAL_TIMEOUT; } *pState = state; @@ -280,9 +282,11 @@ STATUS executeGetCredentialsTurnState(UINT64 customData, UINT64 time) UNUSED_PARAM(time); STATUS retStatus = STATUS_SUCCESS; PTurnConnection pTurnConnection = (PTurnConnection) customData; - + UINT64 currentTime; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); + currentTime = GETTIME(); + if (pTurnConnection->state != TURN_STATE_GET_CREDENTIALS) { /* initialize TLS once tcp connection is established */ /* Start receiving data for TLS handshake */ @@ -294,6 +298,8 @@ STATUS executeGetCredentialsTurnState(UINT64 customData, UINT64 time) CHK_STATUS(socketConnectionInitSecureConnection(pTurnConnection->pControlChannel, FALSE)); } pTurnConnection->state = TURN_STATE_GET_CREDENTIALS; + } else { + CHK(currentTime <= pTurnConnection->stateTimeoutTime, STATUS_TURN_CONNECTION_GET_CREDENTIALS_FAILED); } CHK_STATUS(iceUtilsSendStunPacket(pTurnConnection->pTurnPacket, NULL, 0, &pTurnConnection->turnServer.ipAddress, pTurnConnection->pControlChannel, NULL, FALSE)); @@ -362,7 +368,7 @@ STATUS executeAllocationTurnState(UINT64 customData, UINT64 time) DEFAULT_TURN_ALLOCATION_LIFETIME_SECONDS, &pTurnConnection->pTurnPacket)); pTurnConnection->state = TURN_STATE_ALLOCATION; } else { - CHK(currentTime < pTurnConnection->stateTimeoutTime, STATUS_TURN_CONNECTION_ALLOCATION_FAILED); + CHK(currentTime <= pTurnConnection->stateTimeoutTime, STATUS_TURN_CONNECTION_ALLOCATION_FAILED); } CHK_STATUS(iceUtilsSendStunPacket(pTurnConnection->pTurnPacket, pTurnConnection->longTermKey, ARRAY_SIZE(pTurnConnection->longTermKey), &pTurnConnection->turnServer.ipAddress, pTurnConnection->pControlChannel, NULL, FALSE)); @@ -411,7 +417,7 @@ STATUS fromCreatePermissionTurnState(UINT64 customData, PUINT64 pState) CHK(FALSE, retStatus); } - if (currentTime >= pTurnConnection->stateTimeoutTime || channelWithPermissionCount == pTurnConnection->turnPeerCount) { + if (currentTime > pTurnConnection->stateTimeoutTime || channelWithPermissionCount == pTurnConnection->turnPeerCount) { CHK(channelWithPermissionCount > 0, STATUS_TURN_CONNECTION_FAILED_TO_CREATE_PERMISSION); // go to next state if we have at least one ready peer @@ -523,7 +529,7 @@ STATUS fromBindChannelTurnState(UINT64 customData, PUINT64 pState) readyPeerCount++; } } - if (currentTime >= pTurnConnection->stateTimeoutTime || readyPeerCount == pTurnConnection->turnPeerCount) { + if (currentTime > pTurnConnection->stateTimeoutTime || readyPeerCount == pTurnConnection->turnPeerCount) { CHK(readyPeerCount > 0, STATUS_TURN_CONNECTION_FAILED_TO_BIND_CHANNEL); // go to next state if we have at least one ready peer state = TURN_STATE_READY; @@ -654,7 +660,7 @@ STATUS fromCleanUpTurnState(UINT64 customData, PUINT64 pState) * since we already sent multiple STUN refresh packets with 0 lifetime. */ currentTime = GETTIME(); if (socketConnectionIsClosed(pTurnConnection->pControlChannel) || !ATOMIC_LOAD_BOOL(&pTurnConnection->hasAllocation) || - currentTime >= pTurnConnection->stateTimeoutTime) { + currentTime > pTurnConnection->stateTimeoutTime) { // clean transactionId store for each turn peer, preserving the peers for (i = 0; i < pTurnConnection->turnPeerCount; ++i) { transactionIdStoreClear(pTurnConnection->turnPeerList[i].pTransactionIdStore); From 3752a19749c92a15d581e120deee98512826cd77 Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Wed, 3 Jan 2024 15:43:35 -0800 Subject: [PATCH 3/9] Added internal profiling and SM labels --- samples/Common.c | 2 +- samples/Samples.h | 2 +- src/source/Ice/IceAgent.c | 1 - src/source/Ice/TurnConnection.c | 17 +++++++++++++++-- src/source/Ice/TurnConnection.h | 13 ++++++++++++- src/source/Ice/TurnConnectionStateMachine.c | 10 +++++++--- 6 files changed, 36 insertions(+), 9 deletions(-) diff --git a/samples/Common.c b/samples/Common.c index 1518cee1e6..db38ce0aa4 100644 --- a/samples/Common.c +++ b/samples/Common.c @@ -572,7 +572,7 @@ STATUS initializePeerConnection(PSampleConfiguration pSampleConfiguration, PRtcP configuration.kvsRtcConfiguration.iceSetInterfaceFilterFunc = NULL; // Set the ICE mode explicitly - configuration.iceTransportPolicy = ICE_TRANSPORT_POLICY_ALL; + configuration.iceTransportPolicy = ICE_TRANSPORT_POLICY_RELAY; // Set the STUN server PCHAR pKinesisVideoStunUrlPostFix = KINESIS_VIDEO_STUN_URL_POSTFIX; diff --git a/samples/Samples.h b/samples/Samples.h index 83644c0689..bc182ad769 100644 --- a/samples/Samples.h +++ b/samples/Samples.h @@ -34,7 +34,7 @@ extern "C" { #define CA_CERT_PEM_FILE_EXTENSION ".pem" -#define FILE_LOGGING_BUFFER_SIZE (10 * 1024) +#define FILE_LOGGING_BUFFER_SIZE (10000 * 1024) #define MAX_NUMBER_OF_LOG_FILES 5 #define SAMPLE_HASH_TABLE_BUCKET_COUNT 50 diff --git a/src/source/Ice/IceAgent.c b/src/source/Ice/IceAgent.c index f917667233..4f45dba277 100644 --- a/src/source/Ice/IceAgent.c +++ b/src/source/Ice/IceAgent.c @@ -2400,7 +2400,6 @@ STATUS incomingRelayedDataHandler(UINT64 customData, PSocketConnection pSocketCo CHK(pRelayedCandidate != NULL && pSocketConnection != NULL, STATUS_NULL_ARG); - DLOGV("Candidate id: %s", pRelayedCandidate->id); CHK_STATUS(turnConnectionIncomingDataHandler(pRelayedCandidate->pTurnConnection, pBuffer, bufferLen, pSrc, pDest, turnChannelData, &turnChannelDataCount)); for (i = 0; i < turnChannelDataCount; ++i) { diff --git a/src/source/Ice/TurnConnection.c b/src/source/Ice/TurnConnection.c index 53459a9790..29d06f3e0b 100644 --- a/src/source/Ice/TurnConnection.c +++ b/src/source/Ice/TurnConnection.c @@ -26,7 +26,6 @@ STATUS createTurnConnection(PIceServer pTurnServer, TIMER_QUEUE_HANDLE timerQueu pTurnConnection = (PTurnConnection) MEMCALLOC( 1, SIZEOF(TurnConnection) + DEFAULT_TURN_MESSAGE_RECV_CHANNEL_DATA_BUFFER_LEN * 2 + DEFAULT_TURN_MESSAGE_SEND_CHANNEL_DATA_BUFFER_LEN); CHK(pTurnConnection != NULL, STATUS_NOT_ENOUGH_MEMORY); - pTurnConnection->lock = MUTEX_CREATE(TRUE); pTurnConnection->sendLock = MUTEX_CREATE(FALSE); pTurnConnection->freeAllocationCvar = CVAR_CREATE(); @@ -251,6 +250,11 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, pStunAttributeAddress = (PStunAttributeAddress) pStunAttr; pTurnConnection->relayAddress = pStunAttributeAddress->address; ATOMIC_STORE_BOOL(&pTurnConnection->hasAllocation, TRUE); + CHAR debugStr[256]; + CHAR ipAddrStr[KVS_IP_ADDRESS_STRING_BUFFER_LEN]; + getIpAddrStr(&pTurnConnection->relayAddress, ipAddrStr, ARRAY_SIZE(ipAddrStr)); + SPRINTF(debugStr, "%p - %s:%d - %s", (PVOID)pTurnConnection, ipAddrStr, pTurnConnection->relayAddress.port, "TURN allocation"); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.createAllocationStartTime, pTurnConnection->turnProfileDiagnostics.createAllocationTime, debugStr); if (!pTurnConnection->relayAddressReported && pTurnConnection->turnConnectionCallbacks.relayAddressAvailableFn != NULL) { pTurnConnection->relayAddressReported = TRUE; @@ -291,7 +295,10 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, if (pTurnPeer->connectionState == TURN_PEER_CONN_STATE_CREATE_PERMISSION) { pTurnPeer->connectionState = TURN_PEER_CONN_STATE_BIND_CHANNEL; CHK_STATUS(getIpAddrStr(&pTurnPeer->address, ipAddrStr, ARRAY_SIZE(ipAddrStr))); - DLOGD("create permission succeeded for peer %s", ipAddrStr); + DLOGD("create permission succeeded for peer %s:%d", ipAddrStr, pTurnConnection->relayAddress.port); + CHAR debugStr[256]; + SPRINTF(debugStr, "%p - %s:%d - %s", (PVOID)pTurnConnection, ipAddrStr, pTurnConnection->relayAddress.port, "TURN create permission"); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.createPermissionStartTime, pTurnConnection->turnProfileDiagnostics.createPermissionTime, debugStr); } pTurnPeer->permissionExpirationTime = TURN_PERMISSION_LIFETIME + currentTime; @@ -315,6 +322,9 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, CHK_STATUS(getIpAddrStr(&pTurnPeer->address, ipAddrStr, ARRAY_SIZE(ipAddrStr))); DLOGD("Channel bind succeeded with peer %s, port: %u, channel number %u", ipAddrStr, (UINT16) getInt16(pTurnPeer->address.port), pTurnPeer->channelNumber); + CHAR debugStr[256]; + SPRINTF(debugStr, "%p - %s:%u - %s", (PVOID)pTurnConnection, ipAddrStr, (UINT16) getInt16(pTurnPeer->address.port), "TURN bind channel"); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.bindChannelStartTime, pTurnConnection->turnProfileDiagnostics.bindChannelTime, debugStr); break; } @@ -412,6 +422,9 @@ STATUS turnConnectionHandleStunError(PTurnConnection pTurnConnection, PBYTE pBuf pTurnConnection->turnRealm[pStunAttributeRealm->attribute.length] = '\0'; pTurnConnection->credentialObtained = TRUE; + CHAR debugStr[256]; + SPRINTF(debugStr, "%p - %s", (PVOID)pTurnConnection, "TURN Get Credentials"); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.getCredentialsStartTime, pTurnConnection->turnProfileDiagnostics.getCredentialsTime, debugStr); CHK_STATUS(turnConnectionUpdateNonce(pTurnConnection)); break; diff --git a/src/source/Ice/TurnConnection.h b/src/source/Ice/TurnConnection.h index f1293ffbed..f9fb9fa2cf 100644 --- a/src/source/Ice/TurnConnection.h +++ b/src/source/Ice/TurnConnection.h @@ -99,6 +99,17 @@ typedef struct { BOOL ready; } TurnPeer, *PTurnPeer; +typedef struct { + UINT64 getCredentialsStartTime; + UINT64 getCredentialsTime; + UINT64 createAllocationStartTime; + UINT64 createAllocationTime; + UINT64 createPermissionStartTime; + UINT64 createPermissionTime; + UINT64 bindChannelStartTime; + UINT64 bindChannelTime; +} TurnProfileDiagnostics, *PTurnProfileDiagnostics; + typedef struct __TurnConnection TurnConnection; struct __TurnConnection { volatile ATOMIC_BOOL stopTurnConnection; @@ -165,7 +176,7 @@ struct __TurnConnection { UINT64 currentTimerCallingPeriod; BOOL deallocatePacketSent; - + TurnProfileDiagnostics turnProfileDiagnostics; PStateMachine pStateMachine; }; typedef struct __TurnConnection* PTurnConnection; diff --git a/src/source/Ice/TurnConnectionStateMachine.c b/src/source/Ice/TurnConnectionStateMachine.c index f4333286c9..acc061dfeb 100644 --- a/src/source/Ice/TurnConnectionStateMachine.c +++ b/src/source/Ice/TurnConnectionStateMachine.c @@ -288,6 +288,7 @@ STATUS executeGetCredentialsTurnState(UINT64 customData, UINT64 time) currentTime = GETTIME(); if (pTurnConnection->state != TURN_STATE_GET_CREDENTIALS) { + pTurnConnection->turnProfileDiagnostics.getCredentialsStartTime = currentTime; /* initialize TLS once tcp connection is established */ /* Start receiving data for TLS handshake */ ATOMIC_STORE_BOOL(&pTurnConnection->pControlChannel->receiveData, TRUE); @@ -357,7 +358,7 @@ STATUS executeAllocationTurnState(UINT64 customData, UINT64 time) currentTime = GETTIME(); if (pTurnConnection->state != TURN_STATE_ALLOCATION) { DLOGV("Updated turn allocation request credential after receiving 401"); - + pTurnConnection->turnProfileDiagnostics.createAllocationStartTime = GETTIME(); // update turn allocation packet with credentials CHK_STATUS(freeStunPacket(&pTurnConnection->pTurnPacket)); CHK_STATUS(turnConnectionGetLongTermKey(pTurnConnection->turnServer.username, pTurnConnection->turnRealm, @@ -450,7 +451,7 @@ STATUS executeCreatePermissionTurnState(UINT64 customData, UINT64 time) if (pTurnConnection->state != TURN_STATE_CREATE_PERMISSION) { CHK_STATUS(getIpAddrStr(&pTurnConnection->relayAddress, ipAddrStr, ARRAY_SIZE(ipAddrStr))); DLOGD("Relay address received: %s, port: %u", ipAddrStr, (UINT16) getInt16(pTurnConnection->relayAddress.port)); - + pTurnConnection->turnProfileDiagnostics.createPermissionStartTime = GETTIME(); if (pTurnConnection->pTurnCreatePermissionPacket != NULL) { CHK_STATUS(freeStunPacket(&pTurnConnection->pTurnCreatePermissionPacket)); } @@ -553,7 +554,10 @@ STATUS executeBindChannelTurnState(UINT64 customData, UINT64 time) PTurnConnection pTurnConnection = (PTurnConnection) customData; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); - pTurnConnection->state = TURN_STATE_BIND_CHANNEL; + if(pTurnConnection->state != TURN_STATE_BIND_CHANNEL) { + pTurnConnection->state = TURN_STATE_BIND_CHANNEL; + pTurnConnection->turnProfileDiagnostics.bindChannelStartTime = GETTIME(); + } CHK_STATUS(checkTurnPeerConnections(pTurnConnection)); CleanUp: From 9a681cd514c8d371ea71fd3239adf1da87e2d68d Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Wed, 3 Jan 2024 16:23:09 -0800 Subject: [PATCH 4/9] Add IPv4 check while adding peer --- src/source/Ice/IceAgent.c | 3 ++- src/source/Ice/TurnConnection.c | 1 + 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/src/source/Ice/IceAgent.c b/src/source/Ice/IceAgent.c index 4f45dba277..2dfc443bdd 100644 --- a/src/source/Ice/IceAgent.c +++ b/src/source/Ice/IceAgent.c @@ -517,7 +517,8 @@ STATUS iceAgentAddRemoteCandidate(PIceAgent pIceAgent, PCHAR pIceCandidateString pLocalIceCandidate = (PIceCandidate) pCurNode->data; pCurNode = pCurNode->pNext; - if (pLocalIceCandidate->iceCandidateType == ICE_CANDIDATE_TYPE_RELAYED) { + // TODO: Remove IPv4 check once IPv6 TURN relay candidates are chosen. Disabling this to reduce the number of TURN permissions we create + if (pLocalIceCandidate->iceCandidateType == ICE_CANDIDATE_TYPE_RELAYED && IS_IPV4_ADDR(&pLocalIceCandidate->ipAddress)) { CHK_STATUS(turnConnectionAddPeer(pLocalIceCandidate->pTurnConnection, &pIceCandidate->ipAddress)); } } diff --git a/src/source/Ice/TurnConnection.c b/src/source/Ice/TurnConnection.c index 29d06f3e0b..a995f8b027 100644 --- a/src/source/Ice/TurnConnection.c +++ b/src/source/Ice/TurnConnection.c @@ -289,6 +289,7 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, break; case STUN_PACKET_TYPE_CREATE_PERMISSION_SUCCESS_RESPONSE: + DLOGI("TURN peer count: %d", pTurnConnection->turnPeerCount); for (i = 0; i < pTurnConnection->turnPeerCount; ++i) { pTurnPeer = &pTurnConnection->turnPeerList[i]; if (transactionIdStoreHasId(pTurnPeer->pTransactionIdStore, pBuffer + STUN_PACKET_TRANSACTION_ID_OFFSET)) { From 2ed5ff06e1b6f4e205fe34d37711c65712e1c545 Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Fri, 5 Jan 2024 10:06:24 -0800 Subject: [PATCH 5/9] Nit --- src/source/Ice/TurnConnectionStateMachine.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/source/Ice/TurnConnectionStateMachine.c b/src/source/Ice/TurnConnectionStateMachine.c index acc061dfeb..9969609787 100644 --- a/src/source/Ice/TurnConnectionStateMachine.c +++ b/src/source/Ice/TurnConnectionStateMachine.c @@ -464,7 +464,7 @@ STATUS executeCreatePermissionTurnState(UINT64 customData, UINT64 time) CHK_STATUS(appendStunNonceAttribute(pTurnConnection->pTurnCreatePermissionPacket, pTurnConnection->turnNonce, pTurnConnection->nonceLen)); // create channel bind packet here too so for each peer as soon as permission is created, it can start - // sending chaneel bind request + // sending channel bind request if (pTurnConnection->pTurnChannelBindPacket != NULL) { CHK_STATUS(freeStunPacket(&pTurnConnection->pTurnChannelBindPacket)); } @@ -660,7 +660,7 @@ STATUS fromCleanUpTurnState(UINT64 customData, PUINT64 pState) CHK(FALSE, STATUS_SUCCESS); } - /* start cleanning up even if we dont receive allocation freed response in time, or if connection is already closed, + /* start cleaning up even if we dont receive allocation freed response in time, or if connection is already closed, * since we already sent multiple STUN refresh packets with 0 lifetime. */ currentTime = GETTIME(); if (socketConnectionIsClosed(pTurnConnection->pControlChannel) || !ATOMIC_LOAD_BOOL(&pTurnConnection->hasAllocation) || From 376900b19f535155397daa971b13867e9ce2c0c9 Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Fri, 5 Jan 2024 12:21:36 -0800 Subject: [PATCH 6/9] debug string cleanup --- src/source/Ice/IceAgentStateMachine.c | 2 +- src/source/Ice/TurnConnection.c | 49 ++++++++++++--------- src/source/Ice/TurnConnection.h | 1 + src/source/Ice/TurnConnectionStateMachine.c | 2 +- src/source/Ice/TurnConnectionStateMachine.h | 20 ++++----- 5 files changed, 40 insertions(+), 34 deletions(-) diff --git a/src/source/Ice/IceAgentStateMachine.c b/src/source/Ice/IceAgentStateMachine.c index c569104506..12f808538f 100644 --- a/src/source/Ice/IceAgentStateMachine.c +++ b/src/source/Ice/IceAgentStateMachine.c @@ -605,7 +605,7 @@ STATUS executeReadyIceAgentState(UINT64 customData, UINT64 time) if (pIceAgent->iceAgentStartTime != 0) { PROFILE_WITH_START_TIME_OBJ(pIceAgent->iceAgentStartTime, pIceAgent->iceAgentProfileDiagnostics.iceAgentSetUpTime, - "Time taken to get ICE Agent ready for media exchange"); + "ICE Agent ready for media exchange from check connection start"); pIceAgent->iceAgentStartTime = 0; } diff --git a/src/source/Ice/TurnConnection.c b/src/source/Ice/TurnConnection.c index a995f8b027..362097cb3b 100644 --- a/src/source/Ice/TurnConnection.c +++ b/src/source/Ice/TurnConnection.c @@ -214,6 +214,7 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, PStunAttributeAddress pStunAttributeAddress = NULL; PStunAttributeLifetime pStunAttributeLifetime = NULL; PStunPacket pStunPacket = NULL; + CHAR profileDebugStr[MAX_TURN_PROFILE_LOG_DESC_LEN]; CHAR ipAddrStr[KVS_IP_ADDRESS_STRING_BUFFER_LEN]; BOOL locked = FALSE; ATOMIC_BOOL hasAllocation = FALSE; @@ -244,17 +245,18 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, // convert lifetime to 100ns and store it pTurnConnection->allocationExpirationTime = (pStunAttributeLifetime->lifetime * HUNDREDS_OF_NANOS_IN_A_SECOND) + currentTime; - DLOGD("TURN Allocation succeeded. Life time: %u seconds. Allocation expiration epoch %" PRIu64, pStunAttributeLifetime->lifetime, - pTurnConnection->allocationExpirationTime / DEFAULT_TIME_UNIT_IN_NANOS); pStunAttributeAddress = (PStunAttributeAddress) pStunAttr; pTurnConnection->relayAddress = pStunAttributeAddress->address; ATOMIC_STORE_BOOL(&pTurnConnection->hasAllocation, TRUE); - CHAR debugStr[256]; - CHAR ipAddrStr[KVS_IP_ADDRESS_STRING_BUFFER_LEN]; getIpAddrStr(&pTurnConnection->relayAddress, ipAddrStr, ARRAY_SIZE(ipAddrStr)); - SPRINTF(debugStr, "%p - %s:%d - %s", (PVOID)pTurnConnection, ipAddrStr, pTurnConnection->relayAddress.port, "TURN allocation"); - PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.createAllocationStartTime, pTurnConnection->turnProfileDiagnostics.createAllocationTime, debugStr); + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d - %s", (PVOID) pTurnConnection, ipAddrStr, + pTurnConnection->relayAddress.port, "TURN allocation"); + DLOGD("[%p - %s:%d] TURN Allocation succeeded. Life time: %u seconds. Allocation expiration epoch %" PRIu64, pTurnConnection, ipAddrStr, + pTurnConnection->relayAddress.port, pStunAttributeLifetime->lifetime, + pTurnConnection->allocationExpirationTime / DEFAULT_TIME_UNIT_IN_NANOS); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.createAllocationStartTime, + pTurnConnection->turnProfileDiagnostics.createAllocationTime, profileDebugStr); if (!pTurnConnection->relayAddressReported && pTurnConnection->turnConnectionCallbacks.relayAddressAvailableFn != NULL) { pTurnConnection->relayAddressReported = TRUE; @@ -289,17 +291,17 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, break; case STUN_PACKET_TYPE_CREATE_PERMISSION_SUCCESS_RESPONSE: - DLOGI("TURN peer count: %d", pTurnConnection->turnPeerCount); for (i = 0; i < pTurnConnection->turnPeerCount; ++i) { pTurnPeer = &pTurnConnection->turnPeerList[i]; if (transactionIdStoreHasId(pTurnPeer->pTransactionIdStore, pBuffer + STUN_PACKET_TRANSACTION_ID_OFFSET)) { if (pTurnPeer->connectionState == TURN_PEER_CONN_STATE_CREATE_PERMISSION) { pTurnPeer->connectionState = TURN_PEER_CONN_STATE_BIND_CHANNEL; CHK_STATUS(getIpAddrStr(&pTurnPeer->address, ipAddrStr, ARRAY_SIZE(ipAddrStr))); - DLOGD("create permission succeeded for peer %s:%d", ipAddrStr, pTurnConnection->relayAddress.port); - CHAR debugStr[256]; - SPRINTF(debugStr, "%p - %s:%d - %s", (PVOID)pTurnConnection, ipAddrStr, pTurnConnection->relayAddress.port, "TURN create permission"); - PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.createPermissionStartTime, pTurnConnection->turnProfileDiagnostics.createPermissionTime, debugStr); + DLOGD("[%p] Create permission succeeded for peer %s:%d", pTurnConnection, ipAddrStr, pTurnPeer->address.port); + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d - %s", (PVOID) pTurnConnection, ipAddrStr, + pTurnPeer->address.port, "TURN create permission"); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.createPermissionStartTime, + pTurnConnection->turnProfileDiagnostics.createPermissionTime, profileDebugStr); } pTurnPeer->permissionExpirationTime = TURN_PERMISSION_LIFETIME + currentTime; @@ -321,11 +323,12 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, pTurnPeer->connectionState = TURN_PEER_CONN_STATE_READY; CHK_STATUS(getIpAddrStr(&pTurnPeer->address, ipAddrStr, ARRAY_SIZE(ipAddrStr))); - DLOGD("Channel bind succeeded with peer %s, port: %u, channel number %u", ipAddrStr, (UINT16) getInt16(pTurnPeer->address.port), - pTurnPeer->channelNumber); - CHAR debugStr[256]; - SPRINTF(debugStr, "%p - %s:%u - %s", (PVOID)pTurnConnection, ipAddrStr, (UINT16) getInt16(pTurnPeer->address.port), "TURN bind channel"); - PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.bindChannelStartTime, pTurnConnection->turnProfileDiagnostics.bindChannelTime, debugStr); + DLOGD("[%p] Channel bind succeeded with peer %s, port: %d, channel number %u", pTurnConnection, ipAddrStr, + pTurnPeer->address.port, pTurnPeer->channelNumber); + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d:%u - %s", (PVOID) pTurnConnection, ipAddrStr, + pTurnPeer->address.port, pTurnPeer->channelNumber, "TURN bind channel"); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.bindChannelStartTime, + pTurnConnection->turnProfileDiagnostics.bindChannelTime, profileDebugStr); break; } @@ -371,6 +374,7 @@ STATUS turnConnectionHandleStunError(PTurnConnection pTurnConnection, PBYTE pBuf PStunPacket pStunPacket = NULL; BOOL locked = FALSE, iterate = TRUE; PTurnPeer pTurnPeer = NULL; + CHAR profileDebugStr[MAX_TURN_PROFILE_LOG_DESC_LEN]; UINT32 i; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); @@ -423,10 +427,9 @@ STATUS turnConnectionHandleStunError(PTurnConnection pTurnConnection, PBYTE pBuf pTurnConnection->turnRealm[pStunAttributeRealm->attribute.length] = '\0'; pTurnConnection->credentialObtained = TRUE; - CHAR debugStr[256]; - SPRINTF(debugStr, "%p - %s", (PVOID)pTurnConnection, "TURN Get Credentials"); - PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.getCredentialsStartTime, pTurnConnection->turnProfileDiagnostics.getCredentialsTime, debugStr); - + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s", (PVOID) pTurnConnection, "TURN Get Credentials"); + PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.getCredentialsStartTime, + pTurnConnection->turnProfileDiagnostics.getCredentialsTime, profileDebugStr); CHK_STATUS(turnConnectionUpdateNonce(pTurnConnection)); break; @@ -575,8 +578,8 @@ STATUS turnConnectionHandleChannelDataTcpMode(PTurnConnection pTurnConnection, P /* process only one channel data and return. Because channel data can be intermixed with STUN packet. * need to check remainingBufLen too because channel data could be incomplete. */ while (remainingBufLen != 0 && channelDataCount == 0) { - DLOGV("currRecvDataLen: %d", pTurnConnection->currRecvDataLen); if (pTurnConnection->currRecvDataLen != 0) { + DLOGV("currRecvDataLen: %d", pTurnConnection->currRecvDataLen); if (pTurnConnection->currRecvDataLen >= TURN_DATA_CHANNEL_SEND_OVERHEAD) { /* pTurnConnection->recvDataBuffer always has channel data start */ paddedChannelDataLen = ROUND_UP((UINT32) getInt16(*(PINT16) (pTurnConnection->recvDataBuffer + SIZEOF(channelNumber))), 4); @@ -866,6 +869,7 @@ STATUS turnConnectionRefreshPermission(PTurnConnection pTurnConnection, PBOOL pN UINT64 currTime = 0; PTurnPeer pTurnPeer = NULL; BOOL needRefresh = FALSE; + CHAR ipAddr[KVS_IP_ADDRESS_STRING_BUFFER_LEN]; UINT32 i; CHK(pTurnConnection != NULL && pNeedRefresh != NULL, STATUS_NULL_ARG); @@ -877,7 +881,8 @@ STATUS turnConnectionRefreshPermission(PTurnConnection pTurnConnection, PBOOL pN pTurnPeer = &pTurnConnection->turnPeerList[i]; if (IS_VALID_TIMESTAMP(pTurnPeer->permissionExpirationTime) && currTime + DEFAULT_TURN_PERMISSION_REFRESH_GRACE_PERIOD >= pTurnPeer->permissionExpirationTime) { - DLOGD("Refreshing turn permission"); + getIpAddrStr(&pTurnPeer->address, ipAddr, ARRAY_SIZE(ipAddr)); + DLOGD("[%p] Refreshing turn permission for %s:%d", pTurnConnection, ipAddr, pTurnPeer->address.port); needRefresh = TRUE; } } diff --git a/src/source/Ice/TurnConnection.h b/src/source/Ice/TurnConnection.h index f9fb9fa2cf..a7506fb887 100644 --- a/src/source/Ice/TurnConnection.h +++ b/src/source/Ice/TurnConnection.h @@ -35,6 +35,7 @@ extern "C" { #define DEFAULT_TURN_MESSAGE_RECV_CHANNEL_DATA_BUFFER_LEN MAX_TURN_CHANNEL_DATA_MESSAGE_SIZE #define DEFAULT_TURN_CHANNEL_DATA_BUFFER_SIZE 512 #define DEFAULT_TURN_MAX_PEER_COUNT 32 +#define MAX_TURN_PROFILE_LOG_DESC_LEN 256 // all turn channel numbers must be greater than 0x4000 and less than 0x7FFF #define TURN_CHANNEL_BIND_CHANNEL_NUMBER_BASE (UINT16) 0x4000 diff --git a/src/source/Ice/TurnConnectionStateMachine.c b/src/source/Ice/TurnConnectionStateMachine.c index 9969609787..c39bc22ed7 100644 --- a/src/source/Ice/TurnConnectionStateMachine.c +++ b/src/source/Ice/TurnConnectionStateMachine.c @@ -554,7 +554,7 @@ STATUS executeBindChannelTurnState(UINT64 customData, UINT64 time) PTurnConnection pTurnConnection = (PTurnConnection) customData; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); - if(pTurnConnection->state != TURN_STATE_BIND_CHANNEL) { + if (pTurnConnection->state != TURN_STATE_BIND_CHANNEL) { pTurnConnection->state = TURN_STATE_BIND_CHANNEL; pTurnConnection->turnProfileDiagnostics.bindChannelStartTime = GETTIME(); } diff --git a/src/source/Ice/TurnConnectionStateMachine.h b/src/source/Ice/TurnConnectionStateMachine.h index 9ae2767055..7ec545387a 100644 --- a/src/source/Ice/TurnConnectionStateMachine.h +++ b/src/source/Ice/TurnConnectionStateMachine.h @@ -25,16 +25,16 @@ extern "C" { * TURN_STATE_FAILED: */ -#define TURN_STATE_NONE ((UINT64) 0) -#define TURN_STATE_NEW ((UINT64) (1 << 0)) -#define TURN_STATE_CHECK_SOCKET_CONNECTION ((UINT64) (1 << 1)) -#define TURN_STATE_GET_CREDENTIALS ((UINT64) (1 << 2)) -#define TURN_STATE_ALLOCATION ((UINT64) (1 << 3)) -#define TURN_STATE_CREATE_PERMISSION ((UINT64) (1 << 4)) -#define TURN_STATE_BIND_CHANNEL ((UINT64) (1 << 5)) -#define TURN_STATE_READY ((UINT64) (1 << 6)) -#define TURN_STATE_CLEAN_UP ((UINT64) (1 << 7)) -#define TURN_STATE_FAILED ((UINT64) (1 << 8)) +#define TURN_STATE_NONE ((UINT64) 0) // 0x000000000 +#define TURN_STATE_NEW ((UINT64) (1 << 0)) // 0x000000001 +#define TURN_STATE_CHECK_SOCKET_CONNECTION ((UINT64) (1 << 1)) // 0x000000002 +#define TURN_STATE_GET_CREDENTIALS ((UINT64) (1 << 2)) // 0x000000004 +#define TURN_STATE_ALLOCATION ((UINT64) (1 << 3)) // 0x000000008 +#define TURN_STATE_CREATE_PERMISSION ((UINT64) (1 << 4)) // 0x000000010 +#define TURN_STATE_BIND_CHANNEL ((UINT64) (1 << 5)) // 0x000000020 +#define TURN_STATE_READY ((UINT64) (1 << 6)) // 0x000000040 +#define TURN_STATE_CLEAN_UP ((UINT64) (1 << 7)) // 0x000000080 +#define TURN_STATE_FAILED ((UINT64) (1 << 8)) // 0x000000100 #define TURN_STATE_NONE_STR (PCHAR) "TURN_STATE_NONE" #define TURN_STATE_NEW_STR (PCHAR) "TURN_STATE_NEW" From 831c0045803c403eb050343818c5ac75220b7ae4 Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Fri, 5 Jan 2024 15:38:27 -0800 Subject: [PATCH 7/9] Profile create perm and bind channel only first time and profile per peer --- samples/Common.c | 2 +- src/source/Ice/TurnConnection.c | 32 +++++++++++++++------ src/source/Ice/TurnConnection.h | 12 +++++--- src/source/Ice/TurnConnectionStateMachine.c | 5 ++-- 4 files changed, 36 insertions(+), 15 deletions(-) diff --git a/samples/Common.c b/samples/Common.c index db38ce0aa4..1518cee1e6 100644 --- a/samples/Common.c +++ b/samples/Common.c @@ -572,7 +572,7 @@ STATUS initializePeerConnection(PSampleConfiguration pSampleConfiguration, PRtcP configuration.kvsRtcConfiguration.iceSetInterfaceFilterFunc = NULL; // Set the ICE mode explicitly - configuration.iceTransportPolicy = ICE_TRANSPORT_POLICY_RELAY; + configuration.iceTransportPolicy = ICE_TRANSPORT_POLICY_ALL; // Set the STUN server PCHAR pKinesisVideoStunUrlPostFix = KINESIS_VIDEO_STUN_URL_POSTFIX; diff --git a/src/source/Ice/TurnConnection.c b/src/source/Ice/TurnConnection.c index 362097cb3b..752ee49f2c 100644 --- a/src/source/Ice/TurnConnection.c +++ b/src/source/Ice/TurnConnection.c @@ -298,10 +298,12 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, pTurnPeer->connectionState = TURN_PEER_CONN_STATE_BIND_CHANNEL; CHK_STATUS(getIpAddrStr(&pTurnPeer->address, ipAddrStr, ARRAY_SIZE(ipAddrStr))); DLOGD("[%p] Create permission succeeded for peer %s:%d", pTurnConnection, ipAddrStr, pTurnPeer->address.port); - SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d - %s", (PVOID) pTurnConnection, ipAddrStr, - pTurnPeer->address.port, "TURN create permission"); - PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.createPermissionStartTime, - pTurnConnection->turnProfileDiagnostics.createPermissionTime, profileDebugStr); + if (pTurnPeer->firstTimeCreatePermResponse) { + pTurnPeer->firstTimeCreatePermResponse = FALSE; + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d - %s", (PVOID) pTurnConnection, ipAddrStr, + pTurnPeer->address.port, "TURN create permission"); + PROFILE_WITH_START_TIME_OBJ(pTurnPeer->createPermissionStartTime, pTurnPeer->createPermissionTime, profileDebugStr); + } } pTurnPeer->permissionExpirationTime = TURN_PERMISSION_LIFETIME + currentTime; @@ -325,10 +327,12 @@ STATUS turnConnectionHandleStun(PTurnConnection pTurnConnection, PBYTE pBuffer, CHK_STATUS(getIpAddrStr(&pTurnPeer->address, ipAddrStr, ARRAY_SIZE(ipAddrStr))); DLOGD("[%p] Channel bind succeeded with peer %s, port: %d, channel number %u", pTurnConnection, ipAddrStr, pTurnPeer->address.port, pTurnPeer->channelNumber); - SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d:%u - %s", (PVOID) pTurnConnection, ipAddrStr, - pTurnPeer->address.port, pTurnPeer->channelNumber, "TURN bind channel"); - PROFILE_WITH_START_TIME_OBJ(pTurnConnection->turnProfileDiagnostics.bindChannelStartTime, - pTurnConnection->turnProfileDiagnostics.bindChannelTime, profileDebugStr); + if (pTurnPeer->firstTimeBindChannelResponse) { + pTurnPeer->firstTimeBindChannelResponse = FALSE; + SNPRINTF(profileDebugStr, MAX_TURN_PROFILE_LOG_DESC_LEN, "%p - %s:%d:%u - %s", (PVOID) pTurnConnection, ipAddrStr, + pTurnPeer->address.port, pTurnPeer->channelNumber, "TURN bind channel"); + PROFILE_WITH_START_TIME_OBJ(pTurnPeer->bindChannelStartTime, pTurnPeer->bindChannelTime, profileDebugStr); + } break; } @@ -690,6 +694,10 @@ STATUS turnConnectionAddPeer(PTurnConnection pTurnConnection, PKvsIpAddress pPee pTurnPeer->channelNumber = (UINT16) pTurnConnection->turnPeerCount + TURN_CHANNEL_BIND_CHANNEL_NUMBER_BASE; pTurnPeer->permissionExpirationTime = INVALID_TIMESTAMP_VALUE; pTurnPeer->ready = FALSE; + pTurnPeer->firstTimeCreatePermReq = TRUE; + pTurnPeer->firstTimeBindChannelReq = TRUE; + pTurnPeer->firstTimeCreatePermResponse = TRUE; + pTurnPeer->firstTimeBindChannelResponse = TRUE; CHK_STATUS(xorIpAddress(&pTurnPeer->xorAddress, NULL)); /* only work for IPv4 for now */ CHK_STATUS(createTransactionIdStore(DEFAULT_MAX_STORED_TRANSACTION_ID_COUNT, &pTurnPeer->pTransactionIdStore)); @@ -1031,6 +1039,10 @@ STATUS checkTurnPeerConnections(PTurnConnection pTurnConnection) pTurnPeer = &pTurnConnection->turnPeerList[i]; if (pTurnPeer->connectionState == TURN_PEER_CONN_STATE_CREATE_PERMISSION) { + if (pTurnPeer->firstTimeCreatePermReq) { + pTurnPeer->createPermissionStartTime = GETTIME(); + pTurnPeer->firstTimeCreatePermReq = FALSE; + } // update peer address; CHK_STATUS(getStunAttribute(pTurnConnection->pTurnCreatePermissionPacket, STUN_ATTRIBUTE_TYPE_XOR_PEER_ADDRESS, (PStunAttributeHeader*) &pStunAttributeAddress)); @@ -1047,6 +1059,10 @@ STATUS checkTurnPeerConnections(PTurnConnection pTurnConnection) pTurnConnection->pControlChannel, NULL, FALSE); } else if (pTurnPeer->connectionState == TURN_PEER_CONN_STATE_BIND_CHANNEL) { + if (pTurnPeer->firstTimeBindChannelReq) { + pTurnPeer->bindChannelStartTime = GETTIME(); + pTurnPeer->firstTimeBindChannelReq = FALSE; + } // update peer address; CHK_STATUS(getStunAttribute(pTurnConnection->pTurnChannelBindPacket, STUN_ATTRIBUTE_TYPE_XOR_PEER_ADDRESS, (PStunAttributeHeader*) &pStunAttributeAddress)); diff --git a/src/source/Ice/TurnConnection.h b/src/source/Ice/TurnConnection.h index a7506fb887..6d73d8b336 100644 --- a/src/source/Ice/TurnConnection.h +++ b/src/source/Ice/TurnConnection.h @@ -98,6 +98,14 @@ typedef struct { UINT16 channelNumber; UINT64 permissionExpirationTime; BOOL ready; + BOOL firstTimeCreatePermReq; + BOOL firstTimeCreatePermResponse; + UINT64 createPermissionStartTime; + UINT64 createPermissionTime; + BOOL firstTimeBindChannelReq; + BOOL firstTimeBindChannelResponse; + UINT64 bindChannelStartTime; + UINT64 bindChannelTime; } TurnPeer, *PTurnPeer; typedef struct { @@ -105,10 +113,6 @@ typedef struct { UINT64 getCredentialsTime; UINT64 createAllocationStartTime; UINT64 createAllocationTime; - UINT64 createPermissionStartTime; - UINT64 createPermissionTime; - UINT64 bindChannelStartTime; - UINT64 bindChannelTime; } TurnProfileDiagnostics, *PTurnProfileDiagnostics; typedef struct __TurnConnection TurnConnection; diff --git a/src/source/Ice/TurnConnectionStateMachine.c b/src/source/Ice/TurnConnectionStateMachine.c index c39bc22ed7..dad5240c65 100644 --- a/src/source/Ice/TurnConnectionStateMachine.c +++ b/src/source/Ice/TurnConnectionStateMachine.c @@ -451,7 +451,6 @@ STATUS executeCreatePermissionTurnState(UINT64 customData, UINT64 time) if (pTurnConnection->state != TURN_STATE_CREATE_PERMISSION) { CHK_STATUS(getIpAddrStr(&pTurnConnection->relayAddress, ipAddrStr, ARRAY_SIZE(ipAddrStr))); DLOGD("Relay address received: %s, port: %u", ipAddrStr, (UINT16) getInt16(pTurnConnection->relayAddress.port)); - pTurnConnection->turnProfileDiagnostics.createPermissionStartTime = GETTIME(); if (pTurnConnection->pTurnCreatePermissionPacket != NULL) { CHK_STATUS(freeStunPacket(&pTurnConnection->pTurnCreatePermissionPacket)); } @@ -556,7 +555,6 @@ STATUS executeBindChannelTurnState(UINT64 customData, UINT64 time) CHK(pTurnConnection != NULL, STATUS_NULL_ARG); if (pTurnConnection->state != TURN_STATE_BIND_CHANNEL) { pTurnConnection->state = TURN_STATE_BIND_CHANNEL; - pTurnConnection->turnProfileDiagnostics.bindChannelStartTime = GETTIME(); } CHK_STATUS(checkTurnPeerConnections(pTurnConnection)); @@ -628,6 +626,9 @@ STATUS executeReadyTurnState(UINT64 customData, UINT64 time) ENTERS(); UNUSED_PARAM(time); STATUS retStatus = STATUS_SUCCESS; + UINT64 totalCreatePermTime, totalBindChannelTime; + PTurnPeer pTurnPeer = NULL; + UINT32 i; PTurnConnection pTurnConnection = (PTurnConnection) customData; CHK(pTurnConnection != NULL, STATUS_NULL_ARG); From 7b70f24d25dfc768cee1f89e00c40f06233ed957 Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Mon, 8 Jan 2024 12:54:52 -0800 Subject: [PATCH 8/9] Add README --- README.md | 18 ++++++++++++++++++ .../kinesis/video/webrtcclient/Include.h | 2 +- src/source/Ice/IceAgent.c | 2 +- src/source/Ice/IceAgent.h | 16 ++++++++++------ 4 files changed, 30 insertions(+), 8 deletions(-) diff --git a/README.md b/README.md index 7ac8e6bafe..5a5681f81c 100644 --- a/README.md +++ b/README.md @@ -427,6 +427,24 @@ The threadpool is enabled by default, and starts with 5 threads that it can incr To disable threadpool, run `cmake .. -DENABLE_KVS_THREADPOOL=OFF` +### Setting ICE related timeouts + +There are some default timeout values set for different steps in ICE in the [KvsRtcConfiguration](https://awslabs.github.io/amazon-kinesis-video-streams-webrtc-sdk-c/structKvsRtcConfiguration.html). These are configurable in the application. While the defaults are generous, there could be applications that might need more flexibility to improve chances of connection establishment because of poor network. + +You can find the default setting in the logs: +``` +2024-01-08 19:43:44.433 INFO iceAgentValidateKvsRtcConfig(): + iceLocalCandidateGatheringTimeout: 10000 ms + iceConnectionCheckTimeout: 12000 ms + iceCandidateNominationTimeout: 12000 ms + iceConnectionCheckPollingInterval: 50 ms +``` +Let us look into when each of these could be changed: +1. `iceCandidateNominationTimeout`: Say the connection with host/srflx could not be established and TURN seems to be the only resort. Let us assume it takes about 15 seconds to gather the first local relay candidate, the application could set the timeout to a value more than 15 seconds to ensure candidate pairs with the local relay candidate are tried for success. If the value is set to less than 15 seconds in this case, the SDK would lose out on trying a potential candidate pair leading to connection establishment failure +2. `iceLocalCandidateGatheringTimeout`: Say the host candidates would not work and srflx/relay candidates need to be tried. Due to poor network, it is anticipated the candidates are gathered slowly and the application does not want to spend more than 20 seconds on this step. The goal is to try all possible candidate pairs. Increasing the timeout helps in giving some more time to gather more potential candidates to try for connection. Also note, this parameter increase would not make a difference in the situation unless `iceCandidateNominationTimeout` > `iceLocalCandidateGatheringTimeout` since nomination step should also be given time to work with the new candidates +3. `iceConnectionCheckTimeout`: It is useful to increase this timeout in unstable/slow network where the packet exchange takes time and hence the binding request/response. Essentially, increasing it will allow atleast one candidate pair to be tried for nomination by the other peer. +4. `iceConnectionCheckPollingInterval`: This value is set to a default of 50 ms per [spec](https://datatracker.ietf.org/doc/html/rfc8445#section-14.2). Changing this would change the frequency of connectivity checks and essentially, the ICE state machine transitions. Decreasing the value could help in faster connection establishment in a reliable high performant network setting with good system resources. Increasing the value could help in reducing the network load, however, the connection establishment could slow down. Unless there is a strong reasoning, it is **NOT** recommended to deviate from spec/default. + ## Documentation All Public APIs are documented in our [Include.h](https://github.com/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c/blob/master/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h), we also generate a [Doxygen](https://awslabs.github.io/amazon-kinesis-video-streams-webrtc-sdk-c/) each commit for easier navigation. diff --git a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h index b84133b420..3fcadf5693 100644 --- a/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h +++ b/src/include/com/amazonaws/kinesis/video/webrtcclient/Include.h @@ -1181,7 +1181,7 @@ typedef struct { //!< USE_CANDIDATE attribute. If client is ice controlled, this is the timeout for receiving binding request //!< that has USE_CANDIDATE attribute after connection check is done. Use default value if 0. - UINT32 iceConnectionCheckPollingInterval; //!< Ta in https://tools.ietf.org/html/rfc8445 + UINT32 iceConnectionCheckPollingInterval; //!< Ta in https://datatracker.ietf.org/doc/html/rfc8445#section-14.2 //!< rate at which binding request packets are sent during connection check. Use default interval if 0. INT32 generatedCertificateBits; //!< GeneratedCertificateBits controls the amount of bits the locally generated self-signed certificate uses diff --git a/src/source/Ice/IceAgent.c b/src/source/Ice/IceAgent.c index 2dfc443bdd..b806f13453 100644 --- a/src/source/Ice/IceAgent.c +++ b/src/source/Ice/IceAgent.c @@ -360,7 +360,7 @@ STATUS iceAgentValidateKvsRtcConfig(PKvsRtcConfiguration pKvsRtcConfiguration) pKvsRtcConfiguration->iceConnectionCheckPollingInterval = KVS_ICE_CONNECTION_CHECK_POLLING_INTERVAL; } - DLOGD("\n\ticeLocalCandidateGatheringTimeout: %u ms" + DLOGI("\n\ticeLocalCandidateGatheringTimeout: %u ms" "\n\ticeConnectionCheckTimeout: %u ms" "\n\ticeCandidateNominationTimeout: %u ms" "\n\ticeConnectionCheckPollingInterval: %u ms", diff --git a/src/source/Ice/IceAgent.h b/src/source/Ice/IceAgent.h index f6e1a59852..b692975c1b 100644 --- a/src/source/Ice/IceAgent.h +++ b/src/source/Ice/IceAgent.h @@ -14,12 +14,16 @@ extern "C" { #define KVS_ICE_MAX_REMOTE_CANDIDATE_COUNT 100 #define KVS_ICE_MAX_LOCAL_CANDIDATE_COUNT 100 #define KVS_ICE_GATHER_REFLEXIVE_AND_RELAYED_CANDIDATE_TIMEOUT (10 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_CONNECTIVITY_CHECK_TIMEOUT (10 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_CANDIDATE_NOMINATION_TIMEOUT (10 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_SEND_KEEP_ALIVE_INTERVAL (15 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_TURN_CONNECTION_SHUTDOWN_TIMEOUT (1 * HUNDREDS_OF_NANOS_IN_A_SECOND) -#define KVS_ICE_DEFAULT_TIMER_START_DELAY (3 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) -#define KVS_ICE_SHORT_CHECK_DELAY (50 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) +#define KVS_ICE_CONNECTIVITY_CHECK_TIMEOUT \ + (12 * HUNDREDS_OF_NANOS_IN_A_SECOND) // This should be greater than KVS_ICE_GATHER_REFLEXIVE_AND_RELAYED_CANDIDATE_TIMEOUT to ensure there is + // buffer wait time for connectivity checks with the pairs formed with near timeout created pairs +#define KVS_ICE_CANDIDATE_NOMINATION_TIMEOUT \ + (12 * HUNDREDS_OF_NANOS_IN_A_SECOND) // This should be greater than KVS_ICE_GATHER_REFLEXIVE_AND_RELAYED_CANDIDATE_TIMEOUT to ensure there is some + // buffer for nomination with near timeout generated candidates +#define KVS_ICE_SEND_KEEP_ALIVE_INTERVAL (15 * HUNDREDS_OF_NANOS_IN_A_SECOND) +#define KVS_ICE_TURN_CONNECTION_SHUTDOWN_TIMEOUT (1 * HUNDREDS_OF_NANOS_IN_A_SECOND) +#define KVS_ICE_DEFAULT_TIMER_START_DELAY (3 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) +#define KVS_ICE_SHORT_CHECK_DELAY (50 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) // Ta in https://tools.ietf.org/html/rfc8445 #define KVS_ICE_CONNECTION_CHECK_POLLING_INTERVAL (50 * HUNDREDS_OF_NANOS_IN_A_MILLISECOND) From 48ba5250d441796c6016756088a15114300bb5ab Mon Sep 17 00:00:00 2001 From: Divya Sampath Kumar Date: Mon, 8 Jan 2024 13:40:06 -0800 Subject: [PATCH 9/9] Fix compiler ubused variable warnings --- src/source/Ice/TurnConnectionStateMachine.c | 3 --- 1 file changed, 3 deletions(-) diff --git a/src/source/Ice/TurnConnectionStateMachine.c b/src/source/Ice/TurnConnectionStateMachine.c index dad5240c65..42da265c85 100644 --- a/src/source/Ice/TurnConnectionStateMachine.c +++ b/src/source/Ice/TurnConnectionStateMachine.c @@ -626,9 +626,6 @@ STATUS executeReadyTurnState(UINT64 customData, UINT64 time) ENTERS(); UNUSED_PARAM(time); STATUS retStatus = STATUS_SUCCESS; - UINT64 totalCreatePermTime, totalBindChannelTime; - PTurnPeer pTurnPeer = NULL; - UINT32 i; PTurnConnection pTurnConnection = (PTurnConnection) customData; CHK(pTurnConnection != NULL, STATUS_NULL_ARG);